avocado.core.output: Rename add_console_handler to add_log_handler

The function "add_console_handler" is quite useful. This patch extends
it's capabilities and renames it to fit the new purpose.

Because the new default logging level for "add_log_handler" is INFO,
we add the "avocado.test" and root logger to level DEBUG.

Then finally a few adjustments to the tests that rely on specific
log format and level:

1) selftests/functional/test_multiplex.py: adapt to changes in
test logger That means that extra prefixes ('avocado.test') are
printed out on each line when avocado is run with '--show-job-log'.
While at it, be more precise and check for the specific params at the
specific run with the given variant, instead of looking for a given
param in the output of the three tests variants.

2) selftests/functional/test_standalone.py: adapt to the change of
log prefix ('avocado.test') and extra line because of DEBUG level.
Signed-off-by: NLukáš Doktor <ldoktor@redhat.com>
Signed-off-by: NCleber Rosa <crosa@redhat.com>

avocado/core/job.py

@@ -118,8 +118,8 @@ class Job(object):
 
         if self.show_job_log:
             if not self.silent:
-                output.add_console_handler(_TEST_LOGGER)
-                output.add_console_handler(logging.getLogger())
+                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
 

avocado/core/output.py

@@ -111,16 +111,27 @@ def get_paginator():
     return Paginator()
 
 
-def add_console_handler(logger):
+def add_log_handler(logger, klass=logging.StreamHandler, stream=sys.stdout,
+                    level=logging.INFO, fmt='%(name)s: %(message)s'):
     """
-    Add a console handler to a logger.
-
-    :param logger: `logging.Logger` instance.
+    Add handler to a logger.
+
+    :param logger_name: the name of a :class:`logging.Logger` instance, that
+                        is, the parameter to :func:`logging.getLogger`
+    :param klass: Handler class (defaults to :class:`logging.StreamHandler`)
+    :param stream: Logging stream, to be passed as an argument to ``klass``
+                   (defaults to ``sys.stdout``)
+    :param level: Log level (defaults to `INFO``)
+    :param fmt: Logging format (defaults to ``%(name)s: %(message)s``)
     """
-    console_handler = logging.StreamHandler(sys.stdout)
-    formatter = logging.Formatter(fmt='%(message)s')
-    console_handler.setFormatter(formatter)
-    logger.addHandler(console_handler)
+    handler = klass(stream)
+    handler.setLevel(level)
+    if isinstance(fmt, str):
+        fmt = logging.Formatter(fmt=fmt)
+    handler.setFormatter(fmt)
+    logging.getLogger(logger).addHandler(handler)
+    logging.getLogger(logger).propagate = False
+    return handler
 
 
 class TermSupport(object):

avocado/core/remote/runner.py

@@ -211,7 +211,7 @@ class RemoteTestRunner(TestRunner):
         logger_list = [fabric_logger]
         if self.job.args.show_job_log:
             logger_list.append(app_logger)
-            output.add_console_handler(paramiko_logger)
+            output.add_log_handler(paramiko_logger.name)
         sys.stdout = output.LoggingFile(logger=logger_list)
         sys.stderr = output.LoggingFile(logger=logger_list)
         try:

avocado/core/sysinfo.py

@@ -541,7 +541,7 @@ def collect_sysinfo(args):
 
     :param args: :class:`argparse.Namespace` object with command line params.
     """
-    output.add_console_handler(log)
+    output.add_log_handler(log.name)
 
     basedir = args.sysinfodir
     if not basedir:

selftests/functional/test_multiplex.py

@@ -94,20 +94,27 @@ class MultiplexTests(unittest.TestCase):
         self.run_and_check(cmd_line, expected_rc)
 
     def test_run_mplex_params(self):
-        cmd_line = ('./scripts/avocado run --job-results-dir %s --sysinfo=off examples/tests/env_variables.sh '
-                    '--multiplex examples/tests/env_variables.sh.data'
-                    '/env_variables.yaml '
-                    '--show-job-log' % self.tmpdir)
-        expected_rc = exit_codes.AVOCADO_ALL_OK
-        result = self.run_and_check(cmd_line, expected_rc)
-        for msg in ('A', 'ASDFASDF', 'This is very long\nmultiline\ntext.'):
-            msg = ('[stdout] Custom variable: ' +
-                   '\n[stdout] '.join(msg.splitlines()))
-            self.assertIn(msg, result.stdout, "Multiplexed variable should "
-                                              "produce:"
+        for variant_msg in (('/run/short', 'A'),
+                            ('/run/medium', 'ASDFASDF'),
+                            ('/run/long', 'This is very long\nmultiline\ntext.')):
+            variant, msg = variant_msg
+            cmd_line = ('./scripts/avocado run --job-results-dir %s --sysinfo=off examples/tests/env_variables.sh '
+                        '--multiplex examples/tests/env_variables.sh.data/env_variables.yaml '
+                        '--filter-only %s --show-job-log' % (self.tmpdir, variant))
+            expected_rc = exit_codes.AVOCADO_ALL_OK
+            result = self.run_and_check(cmd_line, expected_rc)
+
+            msg_lines = msg.splitlines()
+            msg_header = '[stdout] Custom variable: %s' % msg_lines[0]
+            self.assertIn(msg_header, result.stdout,
+                          "Multiplexed variable should produce:"
                           "\n  %s\nwhich is not present in the output:\n  %s"
-                          % ("\n  ".join(msg.splitlines()),
-                             "\n  ".join(result.stdout.splitlines())))
+                          % (msg_header, "\n  ".join(result.stdout.splitlines())))
+            for msg_remain in msg_lines[1:]:
+                self.assertIn('[stdout] %s' % msg_remain, result.stdout,
+                              "Multiplexed variable should produce:"
+                              "\n  %s\nwhich is not present in the output:\n  %s"
+                              % (msg_remain, "\n  ".join(result.stdout.splitlines())))
 
     def tearDown(self):
         shutil.rmtree(self.tmpdir)

selftests/functional/test_standalone.py

@@ -51,10 +51,11 @@ 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("\n%s" % exc)
-        self.assertEqual(count, 2, "Exception \\n%s should be present twice in"
-                         "the log (once from the log, second time when parsing"
-                         "exception details." % (exc))
+        count = result.stdout.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 "
+                         "finally from the test results." % (exc))
 
     def test_errortest_nasty2(self):
         cmd_line = './examples/tests/errortest_nasty2.py -r'