From 83a50b5fe6429c6878291df8eccf8f897e5e350e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Luk=C3=A1=C5=A1=20Doktor?= Date: Tue, 23 Feb 2016 17:15:12 +0100 Subject: [PATCH] avocado: Change logging initialization MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This patch changes the way logging is initialized in avocado app: 1. stdout/stderr/logging is replaced with in-memory handlers 2. when arg parsing is done, logging is reconfigured accordingly to setting and re-logs stored messages (when streams are enabled) 3. when job starts and "test" stream is enabled, "" and "avocado.test" streams are enabled 4. when job finishes and "test" stream enabled the additional outputs, the additional outputs are disabled again. The 3 and 4 is necessarily as the "" logger contains all logs including avocado initialization (stevedore, PIL, ...). This way the "test" stream still outputs everything, but only during the job-execution and not during avocado initialization and cleanup. (one can use "early" log to see those). Last but not least it keeps "avocado.app" output in stdout (and stderr), but it moves all other outputs to stderr instead. This is IMO better handling as one can distinguish between debug and "additional" output. Signed-off-by: Lukáš Doktor --- avocado/core/app.py | 35 ++-- avocado/core/job.py | 19 +- avocado/core/log.py | 233 ++++++++++++------------ avocado/core/output.py | 72 ++++++-- avocado/core/parser.py | 31 ++++ selftests/functional/test_basic.py | 16 +- selftests/functional/test_multiplex.py | 8 +- selftests/functional/test_output.py | 6 +- selftests/functional/test_standalone.py | 6 +- 9 files changed, 248 insertions(+), 178 deletions(-) diff --git a/avocado/core/app.py b/avocado/core/app.py index b46581c5..b859045c 100644 --- a/avocado/core/app.py +++ b/avocado/core/app.py @@ -19,7 +19,7 @@ The core Avocado application. import os import signal -from .log import configure as configure_log +from . import log from .parser import Parser from .output import View from .settings import settings @@ -38,20 +38,29 @@ class AvocadoApp(object): # Catch all libc runtime errors to STDERR os.environ['LIBC_FATAL_STDERR_'] = '1' - configure_log() signal.signal(signal.SIGTSTP, signal.SIG_IGN) # ignore ctrl+z self.parser = Parser() - self.cli_dispatcher = CLIDispatcher() - self.cli_cmd_dispatcher = CLICmdDispatcher() - self._print_plugin_failures() - self.parser.start() - if self.cli_cmd_dispatcher.extensions: - self.cli_cmd_dispatcher.map_method('configure', self.parser) - if self.cli_dispatcher.extensions: - self.cli_dispatcher.map_method('configure', self.parser) - self.parser.finish() - if self.cli_dispatcher.extensions: - self.cli_dispatcher.map_method('run', self.parser.args) + log.early_start() + initialized = False + try: + self.cli_dispatcher = CLIDispatcher() + self.cli_cmd_dispatcher = CLICmdDispatcher() + self._print_plugin_failures() + self.parser.start() + if self.cli_cmd_dispatcher.extensions: + self.cli_cmd_dispatcher.map_method('configure', self.parser) + if self.cli_dispatcher.extensions: + self.cli_dispatcher.map_method('configure', self.parser) + self.parser.finish() + if self.cli_dispatcher.extensions: + self.cli_dispatcher.map_method('run', self.parser.args) + initialized = True + finally: + if (not initialized and + getattr(self.parser.args, "silent", False) is False): + log.enable_stderr() + self.parser.args.log = ["app", "test"] + log.reconfigure(self.parser.args) def _print_plugin_failures(self): failures = (self.cli_dispatcher.load_failures + diff --git a/avocado/core/job.py b/avocado/core/job.py index 66f3f944..e5c4b390 100644 --- a/avocado/core/job.py +++ b/avocado/core/job.py @@ -37,6 +37,7 @@ from . import exit_codes from . import exceptions from . import job_id from . import output +from . import log from . import multiplexer from . import tree from . import test @@ -108,20 +109,6 @@ class Job(object): self.loglevel = mapping[raw_log_level] else: self.loglevel = logging.DEBUG - self.show_job_log = getattr(self.args, 'show_job_log', False) - self.silent = getattr(self.args, 'silent', False) - - if self.standalone: - self.show_job_log = True - if self.args is not None: - setattr(self.args, 'show_job_log', True) - - if self.show_job_log: - if not self.silent: - output.add_log_handler(_TEST_LOGGER.name, level=logging.DEBUG) - output.add_log_handler('', level=logging.DEBUG) - _TEST_LOGGER.setLevel(self.loglevel) - _TEST_LOGGER.propagate = False self.test_dir = data_dir.get_test_dir() self.test_index = 1 @@ -533,6 +520,8 @@ class TestProgram(object): os.environ['AVOCADO_STANDALONE_IN_MAIN'] = 'True' self.progName = os.path.basename(sys.argv[0]) + output.add_log_handler("", output.ProgressStreamHandler, + fmt="%(message)s") self.parseArgs(sys.argv[1:]) self.args.url = [sys.argv[0]] self.runTests() @@ -548,6 +537,8 @@ class TestProgram(object): def runTests(self): self.args.standalone = True + self.args.log = ["test"] + log.reconfigure(self.args) self.job = Job(self.args) exit_status = self.job.run() if self.args.remove_test_results is True: diff --git a/avocado/core/log.py b/avocado/core/log.py index 09630a2b..a7a82eee 100644 --- a/avocado/core/log.py +++ b/avocado/core/log.py @@ -13,125 +13,126 @@ # Author: Lucas Meneghel Rodrigues -__all__ = ['configure', 'DEFAULT_LOGGING'] - - +from StringIO import StringIO import logging import os +import sys + +from . import output + + +__all__ = ["early_start", "enable_stderr", "reconfigure"] + if hasattr(logging, 'NullHandler'): - NULL_HANDLER = 'logging.NullHandler' + NULL_HANDLER = logging.NullHandler else: - NULL_HANDLER = 'logutils.NullHandler' - -DEFAULT_LOGGING = { - 'version': 1, - 'disable_existing_loggers': False, - 'formatters': { - 'brief': { - 'format': '%(message)s', - }, - }, - 'filters': { - 'error': { - '()': 'avocado.core.output.FilterError', - }, - 'info': { - '()': 'avocado.core.output.FilterInfo', - }, - }, - 'handlers': { - 'null': { - 'level': 'INFO', - 'class': NULL_HANDLER, - }, - 'console': { - 'level': 'INFO', - 'class': 'logging.StreamHandler', - 'formatter': 'brief', - }, - 'app': { - 'level': 'INFO', - 'class': 'avocado.core.output.ProgressStreamHandler', - 'formatter': 'brief', - 'filters': ['info'], - 'stream': 'ext://sys.stdout', - }, - 'error': { - 'level': 'ERROR', - 'class': 'logging.StreamHandler', - 'formatter': 'brief', - 'filters': ['error'], - }, - 'debug': { - 'level': 'DEBUG', - 'class': 'avocado.core.output.ProgressStreamHandler', - 'formatter': 'brief', - 'stream': 'ext://sys.stdout', - }, - }, - 'loggers': { - '': { - 'handlers': ['null'] - }, - 'avocado': { - 'handlers': ['console'], - }, - 'avocado.app': { - 'handlers': ['app', 'error'], - 'level': 'INFO', - 'propagate': False, - }, - 'avocado.app.tracebacks': { - # Set DEBUG=true to enable debugs - 'handlers': ['error' if os.environ.get('DEBUG') else 'null'], - 'level': 'ERROR', - 'propagate': False, - }, - 'avocado.test': { - 'handlers': ['null'], - 'level': 'DEBUG', - 'propagate': False, - }, - 'avocado.fabric': { - 'handlers': ['null'], - 'level': 'DEBUG', - 'propagate': False, - }, - 'paramiko': { - 'handlers': ['null'], - 'level': 'DEBUG', - 'propagate': False, - }, - 'avocado.test.stdout': { - 'handlers': ['null'], - 'level': 'DEBUG', - 'propagate': False, - }, - 'avocado.test.stderr': { - 'handlers': ['null'], - 'level': 'DEBUG', - 'propagate': False, - }, - 'avocado.sysinfo': { - 'handlers': ['error'], - 'level': 'DEBUG', - 'propagate': False, - }, - 'avocado.debug': { - 'handlers': ['debug'], - 'level': 'DEBUG', - 'propagate': False, - }, - } -} - - -def configure(logging_config=DEFAULT_LOGGING): - from logging import config - if not hasattr(config, 'dictConfig'): - from logutils import dictconfig - cfg_func = dictconfig.dictConfig + import logutils + NULL_HANDLER = logutils.NullHandler + + +STDOUT = sys.stdout +STDERR = sys.stderr + + +def early_start(): + """ + Replace all outputs with in-memory handlers + """ + if os.environ.get('AVOCADO_LOG_DEBUG'): + output.add_log_handler("avocado.app.debug", logging.StreamHandler, + STDERR, logging.DEBUG) + if os.environ.get('AVOCADO_LOG_EARLY'): + output.add_log_handler("", logging.StreamHandler, STDERR, + logging.DEBUG) + output.add_log_handler("avocado.test", logging.StreamHandler, STDERR, + logging.DEBUG) else: - cfg_func = config.dictConfig - cfg_func(logging_config) + sys.stdout = StringIO() + sys.stderr = sys.stdout + output.add_log_handler("", output.MemStreamHandler, None, + logging.DEBUG) + logging.root.level = logging.DEBUG + + +def enable_stderr(): + """ + Enable direct stdout/stderr (useful for handling errors) + """ + if hasattr(sys.stdout, 'getvalue'): + STDERR.write(sys.stdout.getvalue()) + sys.stdout = STDOUT + sys.stderr = STDERR + + +def reconfigure(args): + """ + Adjust logging handlers accordingly to app args and re-log messages. + """ + # Reconfigure stream loggers + enabled = getattr(args, "log", ["app", "early", "debug"]) + if os.environ.get("AVOCADO_LOG_EARLY") and "early" not in enabled: + args.log.append("early") + enabled.append("early") + if os.environ.get("AVOCADO_LOG_DEBUG") and "debug" not in enabled: + args.log.append("debug") + enabled.append("debug") + if getattr(args, "show_job_log", False): + args.log = ["test"] + enabled = ["test"] + if getattr(args, "silent", False): + del args.log[:] + del enabled[:] + if "app" in enabled: + app_logger = logging.getLogger("avocado.app") + app_handler = output.ProgressStreamHandler() + app_handler.setFormatter(logging.Formatter("%(message)s")) + app_handler.addFilter(output.FilterInfo()) + app_handler.stream = STDOUT + app_logger.addHandler(app_handler) + app_logger.propagate = False + app_logger.level = logging.INFO + app_err_handler = output.logging.StreamHandler() + app_err_handler.setFormatter(logging.Formatter("%(message)s")) + app_err_handler.addFilter(output.FilterError()) + app_err_handler.stream = STDERR + app_logger.addHandler(app_err_handler) + app_logger.propagate = False + else: + output.disable_log_handler("avocado.app") + if not os.environ.get("AVOCADO_LOG_EARLY"): + logging.getLogger("avocado.test.stdout").propagate = False + logging.getLogger("avocado.test.stderr").propagate = False + if "early" in enabled: + enable_stderr() + output.add_log_handler("", logging.StreamHandler, STDERR, + logging.DEBUG) + output.add_log_handler("avocado.test", logging.StreamHandler, + STDERR, logging.DEBUG) + else: + # TODO: When stdout/stderr is not used by avocado we should move + # this to output.start_job_logging + sys.stdout = STDOUT + sys.stderr = STDERR + output.disable_log_handler("") + output.disable_log_handler("avocado.test") + if "remote" in enabled: + output.add_log_handler("avocado.fabric", stream=STDERR) + output.add_log_handler("paramiko", stream=STDERR) + else: + output.disable_log_handler("avocado.fabric") + output.disable_log_handler("paramiko") + if not os.environ.get('AVOCADO_LOG_DEBUG'): # Not already enabled by env + if "debug" in enabled: + output.add_log_handler("avocado.app.debug", stream=STDERR) + else: + output.disable_log_handler("avocado.app.debug") + + # Remove the in-memory handlers + for handler in logging.root.handlers: + if isinstance(handler, output.MemStreamHandler): + logging.root.handlers.remove(handler) + + # Log early_messages + for record in output.MemStreamHandler.log: + logging.getLogger(record.name).handle(record) diff --git a/avocado/core/output.py b/avocado/core/output.py index b89afe5a..b46dfe04 100644 --- a/avocado/core/output.py +++ b/avocado/core/output.py @@ -22,6 +22,12 @@ import sys from .settings import settings from ..utils import path as utils_path +if hasattr(logging, 'NullHandler'): + NULL_HANDLER = logging.NullHandler +else: + import logutils + NULL_HANDLER = logutils.NullHandler + class FilterError(logging.Filter): @@ -58,6 +64,24 @@ class ProgressStreamHandler(logging.StreamHandler): self.handleError(record) +class MemStreamHandler(logging.StreamHandler): + + """ + Handler that stores all records in self.log (shared in all instances) + """ + + log = [] + + def emit(self, record): + self.log.append(record) + + def flush(self): + """ + This is in-mem object, it does not require flushing + """ + pass + + class PagerNotFoundError(Exception): pass @@ -134,6 +158,15 @@ def add_log_handler(logger, klass=logging.StreamHandler, stream=sys.stdout, return handler +def disable_log_handler(logger): + logger = logging.getLogger(logger) + # Handlers might be reused elsewhere, can't delete them + while logger.handlers: + logger.handlers.pop() + logger.handlers.append(NULL_HANDLER()) + logger.propagate = False + + class TermSupport(object): COLOR_BLUE = '\033[94m' @@ -412,6 +445,8 @@ class View(object): self.paginator = None self.throbber = Throbber() self.tests_info = {} + self.file_handler = None + self.stream_handler = None def cleanup(self): if self.use_paginator: @@ -478,21 +513,14 @@ class View(object): :param msg: Message to write :type msg: string """ - silent = False - show_job_log = False - if self.app_args is not None: - if hasattr(self.app_args, 'silent'): - silent = self.app_args.silent - if hasattr(self.app_args, 'show_job_log'): - show_job_log = self.app_args.show_job_log - if not (silent or show_job_log): - if self.use_paginator and (level < logging.ERROR): - if not skip_newline: - msg += '\n' - self.paginator.write(msg) - else: - extra = {'skip_newline': skip_newline} - self.console_log.log(level=level, msg=msg, extra=extra) + enabled = getattr(self.app_args, "log", []) + if "app" in enabled and self.use_paginator and level < logging.ERROR: + if not skip_newline: + msg += '\n' + self.paginator.write(msg) + else: + extra = {'skip_newline': skip_newline} + self.console_log.log(level=level, msg=msg, extra=extra) def _log_ui_info(self, msg, skip_newline=False): """ @@ -568,6 +596,7 @@ class View(object): """ self.job_unique_id = unique_id self.debuglog = logfile + # File loggers self.file_handler = logging.FileHandler(filename=logfile) self.file_handler.setLevel(loglevel) @@ -582,16 +611,25 @@ class View(object): root_logger = logging.getLogger() root_logger.addHandler(self.file_handler) root_logger.setLevel(loglevel) + # Console loggers + if ('test' in self.app_args.log and + 'early' not in self.app_args.log): + self.stream_handler = ProgressStreamHandler() + test_logger.addHandler(self.stream_handler) + root_logger.addHandler(self.stream_handler) self.replay_sourcejob = sourcejob def stop_job_logging(self): """ Simple helper for removing a handler from the current logger. """ + # File loggers test_logger = logging.getLogger('avocado.test') - linux_logger = logging.getLogger('avocado.linux') root_logger = logging.getLogger() test_logger.removeHandler(self.file_handler) - linux_logger.removeHandler(self.file_handler) root_logger.removeHandler(self.file_handler) self.file_handler.close() + # Console loggers + if self.stream_handler: + test_logger.removeHandler(self.stream_handler) + root_logger.removeHandler(self.stream_handler) diff --git a/avocado/core/parser.py b/avocado/core/parser.py index 557896e8..a4338de8 100644 --- a/avocado/core/parser.py +++ b/avocado/core/parser.py @@ -29,6 +29,31 @@ PROG = 'avocado' DESCRIPTION = 'Avocado Test Runner' +def log_type(value): + valid_streams = ["app", "test", "debug", "remote", "early", "all", "none"] + value = value.split(',') + if any(_ not in valid_streams for _ in value): + missing = [_ for _ in value if _ not in valid_streams] + msg = ("Invalid logging stream(s): %s\n" + "Supported logging streams are:\n" + " app - application output\n" + " test - test output\n" + " debug - tracebacks and other debugging info\n" + " remote - fabric/paramiko debug\n" + " early - early logging of other streams (very verbose)\n" + " all - everything\n" + " none - disable everything\n" % ", ".join(missing)) + sys.stderr.write(msg) + sys.exit(-1) + + if 'all' in value: + return ["app", "test", "debug", "remote", "early"] + elif 'none' in value: + return [] + else: + return value + + class ArgumentParser(argparse.ArgumentParser): """ @@ -57,6 +82,12 @@ class Parser(object): version='Avocado %s' % VERSION) self.application.add_argument('--config', metavar='CONFIG_FILE', help='Use custom configuration from a file') + self.application.add_argument('--log', action="store", + type=log_type, + metavar='STREAMS', default=['app'], + help="Comma separated list of logging " + "streams to be enabled (app,test,debug," + "remote,early); By default 'app'") def start(self): """ diff --git a/selftests/functional/test_basic.py b/selftests/functional/test_basic.py index 30cc2dfd..e90d03b9 100644 --- a/selftests/functional/test_basic.py +++ b/selftests/functional/test_basic.py @@ -355,11 +355,11 @@ class RunnerHumanOutputTest(unittest.TestCase): self.assertEqual(result.exit_status, expected_rc, "Avocado did not return rc %s:\n%s" % (expected_rc, result)) - self.assertIn('[stdout] foo', result.stdout, result) - self.assertIn('[stdout] \'"', result.stdout, result) - self.assertIn('[stdout] bar/baz', result.stdout, result) + self.assertIn('[stdout] foo', result.stderr, result) + self.assertIn('[stdout] \'"', result.stderr, result) + self.assertIn('[stdout] bar/baz', result.stderr, result) self.assertIn('PASS /bin/echo -ne foo\\\\n\\\'\\"\\\\nbar/baz', - result.stdout, result) + result.stderr, result) # logdir name should escape special chars (/) test_dirs = glob.glob(os.path.join(self.tmpdir, 'latest', 'test-results', '*')) @@ -464,12 +464,12 @@ class RunnerSimpleTest(unittest.TestCase): self.assertEqual(result.exit_status, expected_rc, "Avocado did not return rc %s:\n%s" % (expected_rc, result)) - self.assertIn('DEBUG| Debug message', result.stdout, result) - self.assertIn('INFO | Info message', result.stdout, result) + self.assertIn('DEBUG| Debug message', result.stderr, result) + self.assertIn('INFO | Info message', result.stderr, result) self.assertIn('WARN | Warning message (should cause this test to ' - 'finish with warning)', result.stdout, result) + 'finish with warning)', result.stderr, result) self.assertIn('ERROR| Error message (ordinary message not changing ' - 'the results)', result.stdout, result) + 'the results)', result.stderr, result) def test_non_absolute_path(self): avocado_path = os.path.join(basedir, 'scripts', 'avocado') diff --git a/selftests/functional/test_multiplex.py b/selftests/functional/test_multiplex.py index a53e6608..07accf4a 100644 --- a/selftests/functional/test_multiplex.py +++ b/selftests/functional/test_multiplex.py @@ -106,15 +106,15 @@ class MultiplexTests(unittest.TestCase): msg_lines = msg.splitlines() msg_header = '[stdout] Custom variable: %s' % msg_lines[0] - self.assertIn(msg_header, result.stdout, + self.assertIn(msg_header, result.stderr, "Multiplexed variable should produce:" "\n %s\nwhich is not present in the output:\n %s" - % (msg_header, "\n ".join(result.stdout.splitlines()))) + % (msg_header, "\n ".join(result.stderr.splitlines()))) for msg_remain in msg_lines[1:]: - self.assertIn('[stdout] %s' % msg_remain, result.stdout, + self.assertIn('[stdout] %s' % msg_remain, result.stderr, "Multiplexed variable should produce:" "\n %s\nwhich is not present in the output:\n %s" - % (msg_remain, "\n ".join(result.stdout.splitlines()))) + % (msg_remain, "\n ".join(result.stderr.splitlines()))) def tearDown(self): shutil.rmtree(self.tmpdir) diff --git a/selftests/functional/test_output.py b/selftests/functional/test_output.py index 6a58bf5e..7fc26ea6 100644 --- a/selftests/functional/test_output.py +++ b/selftests/functional/test_output.py @@ -205,10 +205,10 @@ class OutputPluginTest(unittest.TestCase): self.assertEqual(result.exit_status, expected_rc, "Avocado did not return rc %d:\n%s" % (expected_rc, result)) - job_id_list = re.findall('Job ID: (.*)', result.stdout, + job_id_list = re.findall('Job ID: (.*)', result.stderr, re.MULTILINE) - self.assertTrue(job_id_list, 'No Job ID in stdout:\n%s' % - result.stdout) + self.assertTrue(job_id_list, 'No Job ID in stderr:\n%s' % + result.stderr) job_id = job_id_list[0] self.assertEqual(len(job_id), 40) diff --git a/selftests/functional/test_standalone.py b/selftests/functional/test_standalone.py index 4b770e7e..089f2c47 100644 --- a/selftests/functional/test_standalone.py +++ b/selftests/functional/test_standalone.py @@ -51,7 +51,7 @@ class StandaloneTests(unittest.TestCase): expected_rc = exit_codes.AVOCADO_TESTS_FAIL result = self.run_and_check(cmd_line, expected_rc, 'errortest_nasty') exc = "NastyException: Nasty-string-like-exception" - count = result.stdout.count("%s" % exc) + count = result.stderr.count("%s" % exc) self.assertEqual(count, 3, "Exception \\n%s should be present three " "times in the log (first from the traceback, then " "from the test log when raising the exception, and " @@ -62,14 +62,14 @@ class StandaloneTests(unittest.TestCase): expected_rc = exit_codes.AVOCADO_TESTS_FAIL result = self.run_and_check(cmd_line, expected_rc, 'errortest_nasty2') self.assertIn("Exception: Unable to get exception, check the traceback" - " for details.", result.stdout) + " for details.", result.stderr) def test_errortest_nasty3(self): cmd_line = './examples/tests/errortest_nasty3.py -r' expected_rc = exit_codes.AVOCADO_TESTS_FAIL result = self.run_and_check(cmd_line, expected_rc, 'errortest_nasty3') self.assertIn("TestError: