Merge remote-tracking branch 'lmr/log-options-feature-v3'

avocado/core/job.py

@@ -18,6 +18,7 @@ Job module - describes a sequence of automated test operations.
 """
 
 import argparse
+import commands
 import logging
 import os
 import sys
@@ -26,6 +27,7 @@ import tempfile
 import shutil
 import fnmatch
 
+from . import version
 from . import data_dir
 from . import runner
 from . import loader
@@ -36,11 +38,14 @@ from . import exceptions
 from . import job_id
 from . import output
 from . import multiplexer
+from . import tree
 from .settings import settings
+from .plugins import manager
 from .plugins import jsonresult
 from .plugins import xunit
 from .plugins.builtin import ErrorsLoading
 from ..utils import archive
+from ..utils import astring
 from ..utils import path
 from ..utils import runtime
 
@@ -290,6 +295,139 @@ class Job(object):
                     filtered_suite.append(test_template)
         return filtered_suite
 
+    @staticmethod
+    def _log_plugin_load_errors():
+        job_log = _TEST_LOGGER
+        for plugin_failed in ErrorsLoading:
+            job_log.error('Error loading %s -> %s' % plugin_failed)
+        job_log.error('')
+
+    def _log_job_id(self):
+        job_log = _TEST_LOGGER
+        job_log.info('Job ID: %s', self.unique_id)
+        job_log.info('')
+
+    @staticmethod
+    def _log_cmdline():
+        job_log = _TEST_LOGGER
+        cmdline = " ".join(sys.argv)
+        job_log.info("Command line: %s", cmdline)
+        job_log.info('')
+
+    @staticmethod
+    def _log_avocado_version():
+        job_log = _TEST_LOGGER
+        job_log.info('Avocado version: %s', version.VERSION)
+        if os.path.exists('.git') and os.path.exists('avocado.spec'):
+            cmd = "git show --summary --pretty='%H' | head -1"
+            status, top_commit = commands.getstatusoutput(cmd)
+            cmd2 = "git rev-parse --abbrev-ref HEAD"
+            status2, branch = commands.getstatusoutput(cmd2)
+            # Let's display information only if git is installed
+            # (commands succeed).
+            if status == 0 and status2 == 0:
+                job_log.info('Avocado git repo info')
+                job_log.info("Top commit: %s", top_commit)
+                job_log.info("Branch: %s", branch)
+        job_log.info('')
+
+    @staticmethod
+    def _log_avocado_config():
+        job_log = _TEST_LOGGER
+        job_log.info('Config files read (in order):')
+        for cfg_path in settings.config_paths:
+            job_log.info(cfg_path)
+        if settings.config_paths_failed:
+            job_log.info('Config files failed to read (in order):')
+            for cfg_path in settings.config_paths_failed:
+                job_log.info(cfg_path)
+        job_log.info('')
+
+        job_log.info('Avocado config:')
+        header = ('Section.Key', 'Value')
+        config_matrix = []
+        for section in settings.config.sections():
+            for value in settings.config.items(section):
+                config_key = ".".join((section, value[0]))
+                config_matrix.append([config_key, value[1]])
+
+        for line in astring.tabular_output(config_matrix, header).splitlines():
+            job_log.info(line)
+        job_log.info('')
+
+    @staticmethod
+    def _log_avocado_datadir():
+        job_log = _TEST_LOGGER
+        job_log.info('Avocado Data Directories:')
+        job_log.info('')
+        job_log.info("Avocado replaces config dirs that can't be accessed")
+        job_log.info('with sensible defaults. Please edit your local config')
+        job_log.info('file to customize values')
+        job_log.info('')
+        job_log.info('base     ' + data_dir.get_base_dir())
+        job_log.info('tests    ' + data_dir.get_test_dir())
+        job_log.info('data     ' + data_dir.get_data_dir())
+        job_log.info('logs     ' + data_dir.get_logs_dir())
+        job_log.info('')
+
+    @staticmethod
+    def _log_avocado_plugins():
+        job_log = _TEST_LOGGER
+        pm = manager.get_plugin_manager()
+
+        enabled = [p for p in pm.plugins if p.enabled]
+        disabled = [p for p in pm.plugins if not p.enabled]
+
+        if enabled:
+            enabled_matrix = []
+            for plug in sorted(enabled):
+                enabled_matrix.append([plug.name, plug.description])
+            job_log.info("Plugins enabled:")
+            for line in astring.tabular_output(enabled_matrix).splitlines():
+                job_log.info(line)
+
+        if disabled:
+            disabled_matrix = []
+            for plug in sorted(disabled):
+                disabled_matrix.append([plug.name, plug.description])
+            job_log.info("Plugins enabled:")
+            for line in astring.tabular_output(disabled_matrix).splitlines():
+                job_log.info(line)
+
+        if ErrorsLoading:
+            unloadable_matrix = []
+            for load_error in sorted(ErrorsLoading):
+                unloadable_matrix.append([plug.name, "%s -> %s" %
+                                          (load_error[0], load_error[1])])
+
+            job_log.info("Unloadable plugin modules:")
+            for line in astring.tabular_output(unloadable_matrix).splitlines():
+                job_log.info(line)
+
+        job_log.info('')
+
+    def _log_mux_tree(self, mux):
+        job_log = _TEST_LOGGER
+        tree_repr = tree.tree_view(mux.variants.root, verbose=True,
+                                   use_utf8=False)
+        if tree_repr:
+            job_log.info('Multiplex tree representation:')
+            for line in tree_repr.splitlines():
+                job_log.info(line)
+            job_log.info('')
+
+    def _log_job_debug_info(self, mux):
+        """
+        Log relevant debug information to the job log.
+        """
+        self._log_cmdline()
+        self._log_avocado_version()
+        self._log_avocado_plugins()
+        self._log_avocado_config()
+        self._log_avocado_datadir()
+        self._log_mux_tree(mux)
+        self._log_job_id()
+
     def _run(self, urls=None):
         """
         Unhandled job method. Runs a list of test URLs to its completion.
@@ -327,12 +465,7 @@ class Job(object):
                                      self.loglevel,
                                      self.unique_id)
 
-        for plugin_failed in ErrorsLoading:
-            _TEST_LOGGER.error('Error loading %s -> %s' % plugin_failed)
-        _TEST_LOGGER.error('')
-
-        _TEST_LOGGER.info('Job ID: %s', self.unique_id)
-        _TEST_LOGGER.info('')
+        self._log_job_debug_info(mux)
 
         self.view.logfile = self.logfile
         failures = self.test_runner.run_suite(test_suite, mux,

avocado/core/multiplexer.py

@@ -42,6 +42,7 @@ class MuxTree(object):
         """
         :param root: Root of this tree slice
         """
+        self.root = root
         self.pools = []
         for node in self._iter_mux_leaves(root):
             if node.is_leaf:

selftests/all/functional/avocado/multiplex_tests.py

@@ -35,25 +35,9 @@ class MultiplexTests(unittest.TestCase):
     def setUp(self):
         self.tmpdir = tempfile.mkdtemp()
 
-    def run_and_check(self, cmd_line, expected_rc, expected_lines=None):
+    def run_and_check(self, cmd_line, expected_rc):
         os.chdir(basedir)
         result = process.run(cmd_line, ignore_status=True)
-        if expected_lines is not None:
-            for line in result.stdout.splitlines():
-                if 'JOB LOG' in line:
-                    debug_log = line.split()[-1]
-                    debug_log_obj = open(debug_log, 'r')
-                    job_log_lines = debug_log_obj.readlines()
-                    lines_output = len(job_log_lines)
-                    debug_log_obj.close()
-            self.assertGreaterEqual(lines_output, expected_lines,
-                                    'The multiplexed job log output has less '
-                                    'lines than expected\n%s' %
-                                    "".join(job_log_lines))
-            self.assertLess(lines_output, expected_lines * 1.2,
-                            'The multiplexed job log output has more '
-                            'lines than expected\n%s'
-                            % "".join(job_log_lines))
         self.assertEqual(result.exit_status, expected_rc,
                          "Command %s did not return rc "
                          "%d:\n%s" % (cmd_line, expected_rc, result))
@@ -90,15 +74,12 @@ class MultiplexTests(unittest.TestCase):
         cmd_line = ('./scripts/avocado run --job-results-dir %s --sysinfo=off passtest '
                     '--multiplex examples/tests/sleeptest.py.data/sleeptest.yaml' % self.tmpdir)
         expected_rc = 0
-        # Header is 2 lines + 5 lines per each test
-        self.run_and_check(cmd_line, expected_rc, 2 + 5 * 4)
+        self.run_and_check(cmd_line, expected_rc)
 
     def test_run_mplex_doublepass(self):
         cmd_line = ('./scripts/avocado run --job-results-dir %s --sysinfo=off passtest passtest '
                     '--multiplex examples/tests/sleeptest.py.data/sleeptest.yaml' % self.tmpdir)
-        # Header is 2 lines + 5 lines per each test * 2 tests
-        self.run_and_check(cmd_line, expected_rc=0,
-                           expected_lines=2 + 2 * 5 * 4)
+        self.run_and_check(cmd_line, expected_rc=0)
 
     def test_run_mplex_failtest(self):
         cmd_line = ('./scripts/avocado run --job-results-dir %s --sysinfo=off passtest failtest '
@@ -111,9 +92,7 @@ class MultiplexTests(unittest.TestCase):
                     'examples/tests/sleeptest.py.data/sleeptest.yaml '
                     'examples/tests/sleeptest.py.data/sleeptest.yaml' % self.tmpdir)
         expected_rc = 0
-        # Header is 2 lines + 5 lines per each test (mux files are merged thus
-        # only 1x4 variants are generated as in mplex_doublepass test)
-        self.run_and_check(cmd_line, expected_rc, 2 + 5 * 4)
+        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 '