Merge pull request #1042 from clebergnu/logging6_first_round

Refactor logging initialization [subset/first round]

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
 
@@ -405,14 +405,14 @@ class Job(object):
                 that configure a job failure.
         """
         self._setup_job_results()
-        self.view.start_file_logging(self.logfile,
+        self.view.start_job_logging(self.logfile,
                                     self.loglevel,
                                     self.unique_id,
                                     self.replay_sourcejob)
         try:
             test_suite = self._make_test_suite(self.urls)
         except loader.LoaderError, details:
-            stacktrace.log_exc_info(sys.exc_info(), 'avocado.app.tracebacks')
+            stacktrace.log_exc_info(sys.exc_info(), 'avocado.app.debug')
             self._remove_job_results()
             raise exceptions.OptionValidationError(details)
         if not test_suite:
@@ -445,7 +445,7 @@ class Job(object):
         failures = self.test_runner.run_suite(test_suite, mux,
                                               timeout=self.timeout,
                                               replay_map=replay_map)
-        self.view.stop_file_logging()
+        self.view.stop_job_logging()
         # If it's all good so far, set job status to 'PASS'
         if self.status == 'RUNNING':
             self.status = 'PASS'

avocado/core/loader.py

@@ -210,8 +210,7 @@ class TestLoaderProxy(object):
                                    "%s" % (plugin, details),
                                    'avocado.app.exceptions')
             # FIXME: Introduce avocado.traceback logger and use here
-            stacktrace.log_exc_info(sys.exc_info(),
-                                    'avocado.app.tracebacks')
+            stacktrace.log_exc_info(sys.exc_info(), 'avocado.app.debug')
         tests = []
         unhandled_urls = []
         if not urls:

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.
+    Add handler to a logger.
 
-    :param logger: `logging.Logger` instance.
+    :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):
@@ -547,7 +558,7 @@ class View(object):
         """
         self._log_ui_info(term_support.warn_header_str(msg), skip_newline)
 
-    def start_file_logging(self, logfile, loglevel, unique_id, sourcejob=None):
+    def start_job_logging(self, logfile, loglevel, unique_id, sourcejob=None):
         """
         Start the main file logging.
 
@@ -573,7 +584,7 @@ class View(object):
         root_logger.setLevel(loglevel)
         self.replay_sourcejob = sourcejob
 
-    def stop_file_logging(self):
+    def stop_job_logging(self):
         """
         Simple helper for removing a handler from the current logger.
         """

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:

avocado/plugins/html.py

@@ -20,6 +20,7 @@ from avocado.core import exit_codes
 from avocado.core import output
 from avocado.core.html import HTMLTestResult
 from avocado.core.result import register_test_result_class
+
 from .base import CLI
 
 

avocado/plugins/json.py

@@ -16,8 +16,8 @@
 JSON output module.
 """
 
-from avocado.core.result import register_test_result_class
 from avocado.core.jsonresult import JSONTestResult
+from avocado.core.result import register_test_result_class
 
 from .base import CLI
 

avocado/plugins/multiplex.py

@@ -90,7 +90,6 @@ class Multiplex(CLICmd):
         elif not args.tree and args.inherit:
             err = "Option --inherit can be only used with --tree"
         if err:
-            view.notify(event="minor", msg=self.parser.format_help())
             view.notify(event="error", msg=err)
             sys.exit(exit_codes.AVOCADO_FAIL)
         try:

avocado/plugins/remote.py

@@ -14,15 +14,16 @@
 
 """Run tests on a remote machine."""
 
-import sys
 import getpass
+import sys
 
-from avocado.core import output
 from avocado.core import exit_codes
+from avocado.core import output
 from avocado.core import remoter
 from avocado.core.remote import RemoteTestResult
 from avocado.core.remote import RemoteTestRunner
 from avocado.core.result import register_test_result_class
+
 from .base import CLI
 
 

avocado/plugins/vm.py

@@ -14,15 +14,16 @@
 
 """Run tests on Virtual Machine."""
 
-import sys
 import getpass
+import sys
 
-from avocado.core import output
 from avocado.core import exit_codes
+from avocado.core import output
 from avocado.core import virt
 from avocado.core.remote import VMTestResult
 from avocado.core.remote import VMTestRunner
 from avocado.core.result import register_test_result_class
+
 from .base import CLI
 
 

avocado/plugins/wrapper.py

@@ -15,11 +15,12 @@
 import os
 import sys
 
-from .base import CLI
 from avocado.core import exit_codes
 from avocado.core import output
 from avocado.utils import process
 
+from .base import CLI
+
 
 class Wrapper(CLI):
 

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):
+        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 '
-                    '--show-job-log' % self.tmpdir)
+                        '--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)
-        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:"
+
+            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"
+                          % (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"
-                          % ("\n  ".join(msg.splitlines()),
-                             "\n  ".join(result.stdout.splitlines())))
+                              % (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'

selftests/unit/test_jsonresult.py

@@ -12,10 +12,10 @@ from avocado.core import job
 
 class _Stream(object):
 
-    def start_file_logging(self, param1, param2):
+    def start_job_logging(self, param1, param2):
         pass
 
-    def stop_file_logging(self):
+    def stop_job_logging(self):
         pass
 
     def set_tests_info(self, info):

selftests/unit/test_xunit.py

@@ -16,10 +16,10 @@ class ParseXMLError(Exception):
 
 class _Stream(object):
 
-    def start_file_logging(self, param1, param2):
+    def start_job_logging(self, param1, param2):
         pass
 
-    def stop_file_logging(self):
+    def stop_job_logging(self):
         pass
 
     def set_tests_info(self, info):