Improve logging system

* --debug option added
* Logging for exceptions in checkers extended
* Some test coverage improvements
* Added support for external log facility

Change-Id: I856e19a9f22bb1145377ccd5d49e8fc4b9ecf733

muranopkgcheck/cmd/run.py

@@ -19,8 +19,9 @@ import sys
 import six
 
 from muranopkgcheck import log
+from muranopkgcheck import manager
 
-LOG = log.get_logger(__name__)
+LOG = log.getLogger(__name__)
 
 
 def parse_cli_args(args=None):
@@ -49,7 +50,12 @@ def parse_cli_args(args=None):
                         dest='verbose',
                         default=0,
                         action='count',
-                        help='Verbosity level')
+                        help='Verbosity level. -v for ERROR. -vv for INFO')
+
+    parser.add_argument('--debug',
+                        dest='debug',
+                        action='store_true',
+                        help='Set logging level to DEBUG')
 
     parser.add_argument('--discover',
                         dest='discover',
@@ -68,15 +74,14 @@ def setup_logs(args):
         log.setup(level=log.CRITICAL)
     elif args.verbose == 1:
         log.setup(level=log.ERROR)
-    elif args.verbose == 2:
-        log.setup(level=log.INFO)
     else:
+        log.setup(level=log.INFO)
+    if args.debug:
         log.setup(level=log.DEBUG)
 
 
-def run(args, pkg_path=None):
+def run(args, pkg_path=None, quiet_load=False):
-    from muranopkgcheck import manager
+    m = manager.Manager(pkg_path or args.path, quiet_load=quiet_load)
-    m = manager.Manager(pkg_path or args.path)
     m.load_plugins()
     if args.select:
         select = args.select.split(',')
@@ -100,7 +105,7 @@ def discover(args):
                 continue
             try:
                 path = os.path.join(dirpath, item)
-                pkg_errors = run(args, path)
+                pkg_errors = run(args, path, quiet_load=True)
                 LOG.info("Package {} discovered".format(path))
                 if pkg_errors:
                     errors.append("Errors in package {}\n{}\n"
@@ -113,20 +118,17 @@ def discover(args):
 def main():
     args = parse_cli_args()
     setup_logs(args)
-    global LOG
-    LOG = log.get_logger(__name__)
     try:
         if args.discover:
             errors = discover(args)
         else:
             errors = run(args)
-
     except ValueError as e:
-        LOG.critical(e)
+        LOG.error(six.text_type(e))
+        print(six.text_type(e))
         return 2
     except Exception as e:
-        LOG.critical(six.text_type(e))
+        LOG.critical(six.text_type(e), exc_info=sys.exc_info())
-        LOG.exception(e)
         return 3
     if errors:
         print(errors)

muranopkgcheck/log.py

@@ -14,32 +14,41 @@
 
 import logging
 
+import six
+
 CRITICAL = logging.CRITICAL
 ERROR = logging.ERROR
 WARNING = logging.WARNING
 INFO = logging.INFO
 DEBUG = logging.DEBUG
 
-LOG_FORMAT = "%(asctime)s %(name)s:%(lineno)d %(levelname)s %(message)s"
+LOG_FORMAT = "%(name)s:%(lineno)d %(levelname)s %(message)s"
 DEFAULT_LEVEL = logging.DEBUG
-LOG_HANDLER = None
+_loggers = {}
-LOG_LEVEL = DEFAULT_LEVEL
+_logging = None
 
 
-def setup(log_format=LOG_FORMAT, level=DEFAULT_LEVEL):
+def setup(external_logging=None, log_format=LOG_FORMAT, level=DEFAULT_LEVEL):
+
+    if external_logging:
+        global _logging
+        _logging = external_logging
+        return
+
     console_log_handler = logging.StreamHandler()
     console_log_handler.setFormatter(logging.Formatter(log_format))
-    global LOG_HANDLER, LOG_LEVEL
+    global _loggers
-    LOG_HANDLER = console_log_handler
+    for logger in six.itervalues(_loggers):
-    LOG_LEVEL = level
+        logger.setLevel(level)
+        for h in logger.handlers:
+            logger.removeHandler(h)
+        logger.addHandler(console_log_handler)
 
 
-def get_logger(name):
+def getLogger(name):
-    logger = logging.getLogger(name)
+    global _logging, _loggers
-    for h in logger.handlers:
+    if _logging:
-        logger.removeHandler(h)
+        return _logging.getLogger(name)
-    logger.addHandler(LOG_HANDLER)
+    if name not in _loggers:
-    logger.setLevel(LOG_LEVEL)
+        _loggers[name] = logging.getLogger(name)
-    return logger
+    return _loggers[name]
-
-setup()

muranopkgcheck/manager.py

@@ -12,9 +12,13 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import abc
 import itertools
+import pprint
+import sys
 import types
 
+import six
 import stevedore
 
 from muranopkgcheck import error
@@ -22,13 +26,15 @@ from muranopkgcheck import log
 from muranopkgcheck import pkg_loader
 from muranopkgcheck.validators import VALIDATORS
 
-LOG = log.get_logger(__name__)
+LOG = log.getLogger(__name__)
 
 
+@six.add_metaclass(abc.ABCMeta)
 class Formatter(object):
 
+    @abc.abstractmethod
     def format(self, error):
-        pass
+        pass    # pragma: no cover
 
 
 class PlainTextFormatter(Formatter):
@@ -48,9 +54,9 @@ class PlainTextFormatter(Formatter):
 
 class Manager(object):
 
-    def __init__(self, pkg_path):
+    def __init__(self, pkg_path, quiet_load=False):
-        self.pkg = pkg_loader.load_package(pkg_path)
+        self.pkg = pkg_loader.load_package(pkg_path, quiet=quiet_load)
-        self.validators = VALIDATORS
+        self.validators = list(VALIDATORS)
         self.plugins = None
 
     def _to_list(self, error_chain, select=None, ignore=None):
@@ -61,16 +67,36 @@ class Manager(object):
             except StopIteration:
                 break
             except Exception:
-                LOG.exception('Checker failed')
+                exc_info = sys.exc_info()
-                e = error.report.E000(
+                tb = exc_info[2]
-                    'Checker failed more information in logs')
+                while tb.tb_next:
-
+                    tb = tb.tb_next
+                validator_class = tb.tb_frame.f_locals.get('self')
+                check_name = tb.tb_frame.f_code.co_name
+                check_locals = tb.tb_frame.f_locals.copy()
+                check_locals.pop('self', None)
+                if validator_class:
+                    msg = ('Checker {} from {} failed!'
+                           ''.format(check_name,
+                                     validator_class.__class__.__name__))
+                else:
+                    msg = ('Checker {} failed!'
+                           ''.format(check_name))
+                LOG.error('{} {}\n{}'.format(msg,
+                                             'Checker locals:',
+                                             pprint.pformat(check_locals)),
+                          exc_info=exc_info)
+                e = error.report.E000(msg + ' See more information in logs.')
             if isinstance(e, types.GeneratorType):
                 errors.extend(self._to_list(e, select, ignore))
             else:
-                if ((select and e.code not in select)
+                if ((select and e.code not in select) or
-                   or (ignore and e.code in ignore)):
+                        (ignore and e.code in ignore)):
+                    LOG.debug('Skipped: {code} {message}'
+                              ''.format(**e.to_dict()))
                     continue
+                LOG.debug('Reported: {code} {message}'
+                          ''.format(**e.to_dict()))
                 errors.append(e)
 
         return sorted(errors, key=lambda err: err.code)

muranopkgcheck/pkg_loader.py

@@ -27,7 +27,7 @@ from muranopkgcheck import consts
 from muranopkgcheck import log
 from muranopkgcheck import yaml_loader
 
-LOG = log.get_logger(__name__)
+LOG = log.getLogger(__name__)
 
 
 class FileWrapper(object):
@@ -63,7 +63,7 @@ class BaseLoader(object):
     @classmethod
     @abc.abstractmethod
     def _try_load(cls, path):
-        pass
+        pass    # pragma: no cover
 
     @classmethod
     def try_load(cls, path):
@@ -74,15 +74,15 @@ class BaseLoader(object):
 
     @abc.abstractmethod
     def list_files(self, subdir=None):
-        pass
+        pass    # pragma: no cover
 
     @abc.abstractmethod
     def open_file(self, path, mode='r'):
-        pass
+        pass    # pragma: no cover
 
     @abc.abstractmethod
     def exists(self, name):
-        pass
+        pass    # pragma: no cover
 
     def search_for(self, regex='.*', subdir=None):
         r = re.compile(regex)
@@ -103,12 +103,12 @@ class BaseLoader(object):
                             exc_info=sys.exc_info())
             else:
                 if manifest and 'Format' in manifest:
-                    if '/' in str(manifest['Format']):
+                    if '/' in six.text_type(manifest['Format']):
                         fmt, version = manifest['Format'].split('/', 1)
                         self.format = fmt
                         self.format_version = version
                     else:
-                        self.format_version = str(manifest['Format'])
+                        self.format_version = six.text_type(manifest['Format'])
 
 
 class DirectoryLoader(BaseLoader):
@@ -185,13 +185,14 @@ class ZipLoader(BaseLoader):
 PACKAGE_LOADERS = [DirectoryLoader, ZipLoader]
 
 
-def load_package(path):
+def load_package(path, quiet=False):
     for loader_cls in PACKAGE_LOADERS:
         loader = loader_cls.try_load(path)
         if loader is not None:
             return loader
         else:
-            LOG.debug("{} failed to load '{}'"
+            if not quiet:
-                      "".format(loader_cls.__name__, path))
+                LOG.debug("{} failed to load '{}'"
+                          "".format(loader_cls.__name__, path))
     else:
-        raise ValueError("Cannot load package: '{}'".format(path))
+        raise ValueError("Can not load package: '{}'".format(path))

muranopkgcheck/plugin.py

@@ -22,8 +22,8 @@ class Plugin(object):
 
     @abc.abstractmethod
     def validators(self):
-        pass
+        pass    # pragma: no cover
 
     @abc.abstractmethod
     def errors(self):
-        pass
+        pass    # pragma: no cover

muranopkgcheck/tests/test_log.py

@@ -0,0 +1,56 @@
+#    Copyright (c) 2016 Mirantis, Inc.
+#
+#    Licensed under the Apache License, Version 2.0 (the "License"); you may
+#    not use this file except in compliance with the License. You may obtain
+#    a copy of the License at
+#
+#         http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#    WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#    License for the specific language governing permissions and limitations
+#    under the License.
+
+import mock
+
+from muranopkgcheck import log
+from muranopkgcheck.tests import base
+
+
+class LogTest(base.TestCase):
+
+    @mock.patch('muranopkgcheck.log.logging')
+    def test_get_logger(self, m_log):
+        fake_logger = log.getLogger('fake')
+        m_log.getLogger.assert_called_once_with('fake')
+        self.assertEqual(fake_logger, log._loggers['fake'])
+        self.assertEqual(fake_logger, m_log.getLogger.return_value)
+        m_log.reset_mock()
+        fake_logger = log.getLogger('fake')
+        m_log.assert_not_called()
+        self.assertEqual(fake_logger, log._loggers['fake'])
+
+    @mock.patch('muranopkgcheck.log.logging')
+    def test_setup(self, m_log):
+        fake_handler = m_log.StreamHandler.return_value
+        fake_formatter = m_log.Formatter.return_value
+        fake_logger = mock.Mock()
+        fake_old_handler = mock.Mock()
+        fake_logger.handlers = [fake_old_handler]
+        log._loggers['fake'] = fake_logger
+
+        log.setup(log_format='fake_format', level=42)
+
+        m_log.StreamHandler.assert_called_once_with()
+        fake_handler.setFormatter.assert_called_once_with(fake_formatter)
+        fake_logger.setLevel.assert_called_once_with(42)
+        fake_logger.removeHandler.assert_called_once_with(fake_old_handler)
+        fake_logger.addHandler.assert_called_once_with(fake_handler)
+
+    def test_setup_ext_logging(self):
+        fake_logging = mock.Mock()
+        log.setup(external_logging=fake_logging)
+        self.assertEqual(log._logging, fake_logging)
+        log.getLogger('fake_name')
+        fake_logging.getLogger.assert_called_once_with('fake_name')

muranopkgcheck/tests/test_manager.py

@@ -40,28 +40,67 @@ class PlainTextFormatterTest(base.TestCase):
                 self.value = value
                 self.__yaml_meta__ = FakeYamlMeta()
 
-        formater = manager.PlainTextFormatter()
+        formatter = manager.PlainTextFormatter()
         fake_yaml_node = FakeYamlNode('Fake!!!')
 
         errors = [error.report.E007('Fake!!!', fake_yaml_node)]
-        self.assertEqual('fake:1:1: E007 Fake!!!', formater.format(errors))
+        self.assertEqual('fake:1:1: E007 Fake!!!', formatter.format(errors))
 
 
 class ManagerTest(base.TestCase):
 
+    def _assert_errors(self, expected, actual):
+        expected_errors = list(expected)
+        for e in actual:
+            if e in expected_errors:
+                expected_errors.remove(e)
+            else:
+                self.force_failure('Unexpected error {}'.format(e))
+        self.assertEqual([], expected_errors, 'Expected errors left')
+
     @mock.patch('muranopkgcheck.manager.pkg_loader')
-    def test_validate(self, m_pkg_loader):
+    @mock.patch('muranopkgcheck.manager.error.report')
-        fake_error = error.report.E007('Fake!')
+    def test_validate(self, m_error, m_pkg_loader):
+        fake_error = m_error.E007.return_value
+        fake_error.code = 'E007'
+        fake_error.to_dict.return_value = {'code': 'E007', 'message': 'Fake'}
+        fake_E000_error = m_error.E000.return_value
+        fake_E000_error.code = 'E000'
+        fake_E000_error.to_dict.return_value = {'code': 'E000',
+                                                'message': 'Fake'}
 
         def error_generator():
             yield fake_error
+
+        def broken_checker():
+            a = 0
+            if 1 / a:
+                yield fake_error
+
+        def broken_method_checker(self):
+            a = 0
+            if 1 / a:
+                yield fake_error
+
+        mgr = manager.Manager('fake')
+        m_pkg_loader.load_package.assert_called_once_with('fake', quiet=False)
         MockValidator = mock.Mock()
         m_validator = MockValidator.return_value
-        m_validator.run.return_value = (e for e in [
+
-            fake_error,
+        def prepare_errors():
-            error_generator()
+            return iter((fake_error, error_generator(), broken_checker(),
-        ])
+                         broken_method_checker(m_validator)))
-        mgr = manager.Manager('fake')
+
+        m_validator.run.return_value = prepare_errors()
         errors = mgr.validate(validators=[MockValidator])
-        self.assertEqual([fake_error, fake_error], errors)
+        self._assert_errors(
-        m_pkg_loader.load_package.assert_called_once_with('fake')
+            [fake_E000_error, fake_E000_error, fake_error, fake_error],
+            errors)
+
+        m_validator.run.return_value = prepare_errors()
+        errors = mgr.validate(validators=[MockValidator], select=['E007'])
+        self._assert_errors([fake_error, fake_error], errors)
+
+        m_validator.run.return_value = prepare_errors()
+        errors = mgr.validate(validators=[MockValidator], ignore=['E000'])
+        self._assert_errors([fake_error, fake_error], errors)

muranopkgcheck/tests/test_pkg_loader.py

@@ -87,6 +87,13 @@ class BaseLoaderTest(base.TestCase):
             self.assertEqual(consts.DEFAULT_FORMAT, loader.format)
             self.assertEqual('4.2', loader.format_version)
 
+            m_load.return_value = FakeLoader('fake')
+            m_file.yaml.return_value = {}
+            loader = FakeLoader.try_load('fake')
+            self.assertEqual(consts.DEFAULT_FORMAT, loader.format)
+            self.assertEqual(consts.DEFAULT_FORMAT_VERSION,
+                             loader.format_version)
+
     def test_search_for(self):
         fake = FakeLoader('fake')
         self.assertEqual(['1.yaml', 'sub/3.yaml'],

muranopkgcheck/tests/test_plugin.py

@@ -0,0 +1,54 @@
+#    Copyright (c) 2016 Mirantis, Inc.
+#
+#    Licensed under the Apache License, Version 2.0 (the "License"); you may
+#    not use this file except in compliance with the License. You may obtain
+#    a copy of the License at
+#
+#         http://www.apache.org/licenses/LICENSE-2.0
+#
+#    Unless required by applicable law or agreed to in writing, software
+#    distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#    WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#    License for the specific language governing permissions and limitations
+#    under the License.
+
+import mock
+
+from muranopkgcheck import manager
+from muranopkgcheck import plugin
+from muranopkgcheck.tests import test_validator_helpers as helpers
+from muranopkgcheck import validators
+
+
+class FakePlugin(plugin.Plugin):
+
+    def validators(self):
+        pass
+
+    def errors(self):
+        pass
+
+
+class PluginTest(helpers.BaseValidatorTestClass):
+
+    def test_plugin(self):
+        fake = FakePlugin()
+        self.assertIsNotNone(fake)
+
+    @mock.patch('muranopkgcheck.manager.pkg_loader')
+    @mock.patch('muranopkgcheck.manager.stevedore')
+    def test_load_plugins(self, m_stevedore, m_pkg_loader):
+        fake_validator = mock.Mock()
+        fake_plugin = mock.Mock()
+        fake_plugin.obj.validators.return_value = [fake_validator]
+        m_stevedore.ExtensionManager.return_value = [fake_plugin]
+        fake_manager = manager.Manager('fake')
+        m_pkg_loader.load_package.assert_called_once_with('fake', quiet=False)
+        fake_manager.load_plugins()
+        m_stevedore.ExtensionManager.assert_called()
+        self.assertEqual(validators.VALIDATORS + [fake_validator],
+                         fake_manager.validators)
+
+        m_stevedore.ExtensionManager.reset_mock()
+        fake_manager.load_plugins()
+        m_stevedore.ExtensionManager.assert_not_called()

muranopkgcheck/validators/base.py

@@ -21,7 +21,7 @@ import six
 from muranopkgcheck import error
 from muranopkgcheck import log
 
-LOG = log.get_logger(__name__)
+LOG = log.getLogger(__name__)
 FQN_REGEX = re.compile('^([a-zA-Z_$][\w$]*\.)*[a-zA-Z_$][\w$]*$')
 NAME_REGEX = re.compile('^[A-Za-z_][\w]*$')