avocado: Change logging initialization

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: NLukáš Doktor <ldoktor@redhat.com>

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 +

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:

avocado/core/log.py

@@ -13,125 +13,126 @@
 # Author: Lucas Meneghel Rodrigues <lmr@redhat.com>
 
 
-__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)

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)

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):
         """

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')

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)

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)
 

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: <errortest_nasty3.NastyException instance at ",
-                      result.stdout)
+                      result.stderr)
 
     def test_errortest(self):
         cmd_line = './examples/tests/errortest.py -r'