logging: port to standard Python logging

Use the standard `logging` module to configure logging instead of the
in-house `ipapython.log_manager` module and remove `ipapython.log_manager`.

Disable the logging-not-lazy and logging-format-interpolation pylint
checks.

Reviewed-By: Martin Basti <mbasti@redhat.com>

ipaclient/install/client.py

@@ -13,6 +13,8 @@ from __future__ import (
     absolute_import,
 )
 
+import logging
+
 import dns
 import getpass
 import gssapi
@@ -51,7 +53,7 @@ from ipapython.dn import DN
 from ipapython.install import typing
 from ipapython.install.core import group, knob, extend_knob
 from ipapython.install.common import step
-from ipapython.ipa_log_manager import log_mgr, root_logger
+from ipapython.ipa_log_manager import root_logger
 from ipapython.ipautil import (
     CalledProcessError,
     dir_exists,
@@ -3366,9 +3368,12 @@ def uninstall(options):
 
 
 def init(installer):
-    try:
-        installer.debug = log_mgr.get_handler('console').level == 'debug'
-    except KeyError:
+    for handler in root_logger.handlers:
+        if (isinstance(handler, logging.StreamHandler) and
+                handler.stream is sys.stderr):  # pylint: disable=no-member
+            installer.debug = handler.level == logging.DEBUG
+            break
+    else:
         installer.debug = True
     installer.unattended = not installer.interactive
 

ipalib/plugable.py

@@ -24,7 +24,9 @@ The classes in this module make heavy use of Python container emulation. If
 you are unfamiliar with this Python feature, see
 http://docs.python.org/ref/sequence-types.html
 """
+import logging
 import operator
+import re
 import sys
 import threading
 import os
@@ -42,7 +44,7 @@ from ipalib.text import _
 from ipalib.util import classproperty
 from ipalib.base import ReadOnly, lock, islocked
 from ipalib.constants import DEFAULT_CONFIG
-from ipapython import ipautil
+from ipapython import ipa_log_manager, ipautil
 from ipapython.ipa_log_manager import (
     log_mgr,
     LOGGING_FORMAT_FILE,
@@ -439,28 +441,63 @@ class API(ReadOnly):
             parser = self.build_global_parser()
         self.parser = parser
 
+        root_logger = ipa_log_manager.root_logger
+
         # If logging has already been configured somewhere else (like in the
         # installer), don't add handlers or change levels:
-        if log_mgr.configure_state != 'default' or self.env.validate_api:
+        if root_logger.handlers or self.env.validate_api:
             return
 
-        log_mgr.default_level = 'info'
-        log_mgr.configure_from_env(self.env, configure_state='api')
-        # Add stderr handler:
-        level = 'info'
         if self.env.debug:
-            level = 'debug'
+            level = logging.DEBUG
+        else:
+            level = logging.INFO
+        root_logger.setLevel(level)
+
+        for attr in self.env:
+            match = re.match(r'^log_logger_level_'
+                             r'(debug|info|warn|warning|error|critical|\d+)$',
+                             attr)
+            if not match:
+                continue
+
+            value = match.group(1)
+            try:
+                level = int(value)
+            except ValueError:
+                try:
+                    level = {
+                        'debug': logging.DEBUG,
+                        'info': logging.INFO,
+                        'warn': logging.WARNING,
+                        'warning': logging.WARNING,
+                        'error': logging.ERROR,
+                        'critical': logging.CRITICAL
+                    }[value]
+                except KeyError:
+                    raise ValueError('unknown log level (%s)' % value)
+
+            value = getattr(self.env, attr)
+            regexps = re.split('\s*,\s*', value)
+
+            # Add the regexp, it maps to the configured level
+            for regexp in regexps:
+                root_logger.addFilter(ipa_log_manager.Filter(regexp, level))
+
+        # Add stderr handler:
+        level = logging.INFO
+        if self.env.debug:
+            level = logging.DEBUG
         else:
             if self.env.context == 'cli':
                 if self.env.verbose > 0:
-                    level = 'info'
+                    level = logging.INFO
                 else:
-                    level = 'warning'
-
-        log_mgr.create_log_handlers([dict(name='console',
-                                          stream=sys.stderr,
-                                          level=level,
-                                          format=LOGGING_FORMAT_STDERR)])
+                    level = logging.WARNING
+        handler = logging.StreamHandler()
+        handler.setLevel(level)
+        handler.setFormatter(ipa_log_manager.Formatter(LOGGING_FORMAT_STDERR))
+        root_logger.addHandler(handler)
 
         # Add file handler:
         if self.env.mode in ('dummy', 'unit_test'):
@@ -475,17 +512,17 @@ class API(ReadOnly):
                 log.error('Could not create log_dir %r', log_dir)
                 return
 
-        level = 'info'
+        level = logging.INFO
         if self.env.debug:
-            level = 'debug'
+            level = logging.DEBUG
         try:
-            log_mgr.create_log_handlers([dict(name='file',
-                                              filename=self.env.log,
-                                              level=level,
-                                              format=LOGGING_FORMAT_FILE)])
+            handler = logging.FileHandler(self.env.log)
         except IOError as e:
             log.error('Cannot open log file %r: %s', self.env.log, e)
             return
+        handler.setLevel(level)
+        handler.setFormatter(ipa_log_manager.Formatter(LOGGING_FORMAT_FILE))
+        root_logger.addHandler(handler)
 
     def build_global_parser(self, parser=None, context=None):
         """

ipapython/admintool.py

@@ -22,6 +22,7 @@
 Handles common operations like option parsing and logging
 """
 
+import logging
 import sys
 import os
 import traceback
@@ -230,8 +231,12 @@ class AdminTool(object):
         Logging to file is only set up after option validation and prompting;
         before that, all output will go to the console only.
         """
-        if 'console' in ipa_log_manager.log_mgr.handlers:
-            ipa_log_manager.log_mgr.remove_handler('console')
+        root_logger = ipa_log_manager.root_logger
+        for handler in root_logger.handlers:
+            if (isinstance(handler, logging.StreamHandler) and
+                    handler.stream is sys.stderr):  # pylint: disable=no-member
+                root_logger.removeHandler(handler)
+                break
 
         self._setup_logging(log_file_mode=log_file_mode)
 

ipapython/ipa_log_manager.py

@@ -16,23 +16,19 @@
 # You should have received a copy of the GNU General Public License
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 
-#-------------------------------------------------------------------------------
+import logging
+import os
+import re
+import time
+import sys
+
+import six
 
 # Module exports
 __all__ = ['log_mgr', 'root_logger', 'standard_logging_setup',
            'IPA_ROOT_LOGGER_NAME', 'ISO8601_UTC_DATETIME_FMT',
            'LOGGING_FORMAT_STDERR', 'LOGGING_FORMAT_STDOUT', 'LOGGING_FORMAT_FILE']
 
-#-------------------------------------------------------------------------------
-
-import sys
-import re
-import copy
-
-from ipapython.log_manager import LogManager, parse_log_level
-
-#-------------------------------------------------------------------------------
-
 # Our root logger, all loggers will be descendents of this.
 IPA_ROOT_LOGGER_NAME = 'ipa'
 
@@ -62,159 +58,88 @@ LOGGING_FORMAT_STANDARD_CONSOLE = '%(name)-12s: %(levelname)-8s %(message)s'
 # Used by standard_logging_setup() for file message
 LOGGING_FORMAT_STANDARD_FILE = '%(asctime)s %(levelname)s %(message)s'
 
-#-------------------------------------------------------------------------------
 
-class IPALogManager(LogManager):
-    '''
-    Subclass the LogManager to enforce some IPA specfic logging
-    conventions.
+def get_logger(who, bind_logger_names=False):
+    if isinstance(who, six.string_types):
+        obj_name = who
+    else:
+        obj_name = '%s.%s' % (who.__module__, who.__class__.__name__)
 
-    * Default to timestamps in UTC.
-    * Default to ISO 8601 timestamp format.
-    * Default the message format.
-    '''
+    if obj_name == IPA_ROOT_LOGGER_NAME:
+        logger_name = obj_name
+    else:
+        logger_name = IPA_ROOT_LOGGER_NAME + '.' + obj_name
 
-    log_logger_level_config_re = re.compile(r'^log_logger_level_(debug|info|warn|warning|error|critical|\d+)$')
+    logger = logging.getLogger(logger_name)
 
-    def __init__(self, configure_state=None):
-        '''
-        :parameters:
-          configure_state
-            Used by clients of the log manager to track the
-            configuration state, may be any object.
-        '''
+    if bind_logger_names:
+        method = 'log'
+        if hasattr(who, method):
+            raise ValueError('%s is already bound to %s' % (method, repr(who)))
+        setattr(who, method, logger)
 
-        super(IPALogManager, self).__init__(IPA_ROOT_LOGGER_NAME, configure_state)
+        for method in ('debug',
+                       'info',
+                       'warning',
+                       'error',
+                       'exception',
+                       'critical'):
+            if hasattr(who, method):
+                raise ValueError(
+                    '%s is already bound to %s' % (method, repr(who)))
+            setattr(who, method, getattr(logger, method))
 
-    def configure_from_env(self, env, configure_state=None):
-        '''
-        Read the loggger configuration from the Env config. The
-        following items may be configured:
+    return logger
 
-        Logger Levels
-          *log_logger_XXX = comma separated list of regexps*
 
-          Logger levels can be explicitly specified for specific loggers as
-          opposed to a global logging level. Specific loggers are indiciated
-          by a list of regular expressions bound to a level. If a logger's
-          name matches the regexp then it is assigned that level. The keys
-          in the Env config must begin with "log_logger_level\_" and then be
-          followed by a symbolic or numeric log level, for example::
+class Filter(object):
+    def __init__(self, regexp, level):
+        self.regexp = re.compile(regexp)
+        self.level = level
 
-            log_logger_level_debug = ipapython\.dn\..*
-            log_logger_level_35 = ipalib\.plugins\.dogtag
+    def filter(self, record):
+        return (not self.regexp.match(record.name) or
+                record.levelno >= self.level)
 
-          The first line says any logger belonging to the ipapython.dn module
-          will have it's level configured to debug.
 
-          The second line say the ipa.plugins.dogtag logger will be
-          configured to level 35.
+class Formatter(logging.Formatter):
+    def __init__(
+            self, fmt=LOGGING_FORMAT_STDOUT, datefmt=ISO8601_UTC_DATETIME_FMT):
+        super(Formatter, self).__init__(fmt, datefmt)
+        self.converter = time.gmtime
 
-          Note: logger names are a dot ('.') separated list forming a path
-          in the logger tree.  The dot character is also a regular
-          expression metacharacter (matches any character) therefore you
-          will usually need to escape the dot in the logger names by
-          preceeding it with a backslash.
-
-        The return value of this function is a dict with the following
-        format:
-
-        logger_regexps
-          List of (regexp, level) tuples
-
-        :parameters:
-          env
-            Env object configuration values are read from.
-          configure_state
-            If other than None update the log manger's configure_state
-            variable to this object. Clients of the log manager can
-            use configure_state to track the state of the log manager.
-        '''
-        logger_regexps = []
-        config = {'logger_regexps' : logger_regexps,
-                 }
-
-        for attr in ('debug', 'verbose'):
-            value = getattr(env, attr, None)
-            if value is not None:
-                config[attr] = value
-
-        for attr in list(env):
-            # Get logger level configuration
-            match = IPALogManager.log_logger_level_config_re.search(attr)
-            if match:
-                value = match.group(1)
-                level = parse_log_level(value)
-                value = getattr(env, attr)
-                regexps = re.split('\s*,\s*', value)
-                # Add the regexp, it maps to the configured level
-                for regexp in regexps:
-                    logger_regexps.append((regexp, level))
-                continue
-
-        self.configure(config, configure_state)
-        return config
-
-    def create_log_handlers(self, configs, logger=None, configure_state=None):
-        'Enforce some IPA specific configurations'
-        configs = copy.copy(configs)
-
-        for cfg in configs:
-            if not 'time_zone_converter' in cfg:
-                cfg['time_zone_converter'] = 'utc'
-            if not 'datefmt' in cfg:
-                cfg['datefmt'] = ISO8601_UTC_DATETIME_FMT
-            if not 'format' in cfg:
-                cfg['format'] = LOGGING_FORMAT_STDOUT
-
-        return super(IPALogManager, self).create_log_handlers(configs, logger, configure_state)
-
-#-------------------------------------------------------------------------------
 
 def standard_logging_setup(filename=None, verbose=False, debug=False,
                            filemode='w', console_format=None):
     if console_format is None:
         console_format = LOGGING_FORMAT_STANDARD_CONSOLE
 
-    handlers = []
+    root_logger.setLevel(logging.DEBUG)
 
     # File output is always logged at debug level
     if filename is not None:
-        file_handler = dict(name='file',
-                            filename=filename,
-                            filemode=filemode,
-                            permission=0o600,
-                            level='debug',
-                            format=LOGGING_FORMAT_STANDARD_FILE)
-        handlers.append(file_handler)
+        umask = os.umask(0o177)
+        try:
+            file_handler = logging.FileHandler(filename, mode=filemode)
+        finally:
+            os.umask(umask)
+        file_handler.setLevel(logging.DEBUG)
+        file_handler.setFormatter(Formatter(LOGGING_FORMAT_STANDARD_FILE))
+        root_logger.addHandler(file_handler)
 
-    level = 'error'
+    level = logging.ERROR
     if verbose:
-        level = 'info'
+        level = logging.INFO
     if debug:
-        level = 'debug'
+        level = logging.DEBUG
 
-    console_handler = dict(name='console',
-                           stream=sys.stderr,
-                           level=level,
-                           format=console_format)
-    handlers.append(console_handler)
+    console_handler = logging.StreamHandler()
+    console_handler.setLevel(level)
+    console_handler.setFormatter(Formatter(console_format))
+    root_logger.addHandler(console_handler)
 
 
-    # default_level must be debug becuase we want the file handler to
-    # always log at the debug level.
-    log_mgr.configure(dict(default_level='debug',
-                           handlers=handlers),
-                      configure_state='standard')
-
-    return log_mgr.root_logger
-
-#-------------------------------------------------------------------------------
-
 # Single shared instance of log manager
+log_mgr = sys.modules[__name__]
 
-log_mgr = IPALogManager()
-log_mgr.configure(dict(default_level='error',
-                       handlers=[]),
-                  configure_state='default')
-root_logger = log_mgr.root_logger
+root_logger = logging.getLogger(IPA_ROOT_LOGGER_NAME)

ipaserver/advise/base.py

@@ -20,6 +20,7 @@
 from __future__ import print_function
 
 from contextlib import contextmanager
+import logging
 import os
 from textwrap import wrap
 
@@ -28,7 +29,7 @@ from ipalib.plugable import Plugin, API
 from ipalib.errors import ValidationError
 from ipaplatform.paths import paths
 from ipapython import admintool
-from ipapython.ipa_log_manager import log_mgr
+from ipapython.ipa_log_manager import Filter, root_logger
 
 
 """
@@ -507,7 +508,7 @@ class IpaAdvise(admintool.AdminTool):
         if not self.options.verbose:
             # Do not print connection information by default
             logger_name = r'ipa\.ipalib\.plugins\.rpcclient'
-            log_mgr.configure(dict(logger_regexps=[(logger_name, 'warning')]))
+            root_logger.addFilter(Filter(logger_name, logging.WARNING))
 
         # With no argument, print the list out and exit
         if not self.args:

ipatests/pytest_plugins/beakerlib.py

@@ -25,20 +25,18 @@ If the plugin is active, sets up IPA logging to also log to Beaker.
 
 import logging
 
-from ipapython.ipa_log_manager import log_mgr
+from ipapython.ipa_log_manager import Formatter, root_logger
 
 
 def pytest_configure(config):
     plugin = config.pluginmanager.getplugin('BeakerLibPlugin')
     if plugin:
+        root_logger.setLevel(logging.DEBUG)
+
         handler = BeakerLibLogHandler(plugin.run_beakerlib_command)
-        log_mgr.configure(
-            {
-                'default_level': 'DEBUG',
-                'handlers': [{'log_handler': handler,
-                              'format': '[%(name)s] %(message)s',
-                              'level': 'info'}]},
-            configure_state='beakerlib_plugin')
+        handler.setLevel(logging.INFO)
+        handler.setFormatter(Formatter('[%(name)s] %(message)s'))
+        root_logger.addHandler(handler)
 
 
 class BeakerLibLogHandler(logging.Handler):

ipatests/pytest_plugins/nose_compat.py

@@ -23,7 +23,7 @@ import os
 import sys
 import logging
 
-from ipapython.ipa_log_manager import log_mgr
+from ipapython.ipa_log_manager import Formatter, root_logger
 
 
 def pytest_addoption(parser):
@@ -61,13 +61,7 @@ def pytest_configure(config):
                     capture._capturing.resume_capturing()
                 sys.stdout, sys.stderr = orig_stdout, orig_stderr
 
-        log_mgr.configure(
-            {
-                'default_level': config.getoption('logging_level'),
-                'handlers': [{'log_handler': LogHandler(),
-                            'format': '[%(name)s] %(message)s',
-                            'level': 'debug'},
-                            {'level': 'debug',
-                            'name': 'real_stderr',
-                            'stream': sys.stderr}]},
-            configure_state='tests')
+        handler = LogHandler()
+        handler.setFormatter(Formatter('[%(name)s] %(message)s'))
+        handler.setLevel(config.getoption('logging_level'))
+        root_logger.addHandler(handler)

pylintrc

@@ -94,6 +94,8 @@ disable=
     consider-merging-isinstance,  # new in pylint 1.7
     unsupported-assignment-operation  # new in pylint 1.7
     consider-iterating-dictionary,  # wontfix for better python2/3 code
+    logging-not-lazy,
+    logging-format-interpolation,
 
 
 [REPORTS]