software: added custom cmpi_logging

use custom cmpi_logging module

made logging configurable

1 files changed, 282 insertions, 0 deletions

diff --git a/src/software/lmi/software/util/cmpi_logging.py b/src/software/lmi/software/util/cmpi_logging.py
new file mode 100644
index 0000000..b3a76c4
--- /dev/null
+++ b/src/software/lmi/software/util/cmpi_logging.py
@@ -0,0 +1,282 @@
+# Software Management Providers
+#
+# Copyright (C) 2012-2013 Red Hat, Inc.  All rights reserved.
+#
+# This library is free software; you can redistribute it and/or
+# modify it under the terms of the GNU Lesser General Public
+# License as published by the Free Software Foundation; either
+# version 2.1 of the License, or (at your option) any later version.
+#
+# This library is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+# Lesser General Public License for more details.
+#
+# You should have received a copy of the GNU Lesser General Public
+# License along with this library; if not, write to the Free Software
+# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301  USA
+#
+# Authors: Michal Minar <miminar@redhat.com>
+#
+"""
+Module devoted to logging facilities.
+"""
+
+import inspect
+from itertools import chain
+import logging
+import logging.config
+import os
+
+from lmi.common import cmpi_logging
+
+DEFAULT_LOGGING_CONFIG = {
+    "version" : 1,
+    'disable_existing_loggers' : True,
+    "formatters": {
+        # this is a message format for logging function/method calls
+        # it's manually set up in YumWorker's init method
+        "default": {
+            "()": "lmi.software.util.cmpi_logging.DispatchingFormatter",
+            "formatters" : {
+                "lmi.software.util.cmpi_logging.trace_function_or_method":
+                    "%(levelname)s:%(message)s"
+                },
+            "default" : "%(levelname)s:%(module)s:"
+                        "%(funcName)s:%(lineno)d - %(message)s"
+            },
+        },
+    "handlers": {
+        "stderr" : {
+            "class" : "logging.StreamHandler",
+            "level" : "ERROR",
+            "formatter": "default",
+            },
+        "cmpi" : {
+            "()"    : "lmi.common.cmpi_logging.CMPILogHandler",
+            # this must be filled with broker env logger
+            "cmpi_logger" : None,
+            "level" : "ERROR",
+            "formatter" : "default"
+            },
+        },
+    "root": {
+        "level": "ERROR",
+        "handlers" : ["cmpi"],
+        },
+    }
+
+LOGGING_LEVELS = {
+        "critical"      : logging.CRITICAL,
+        "error"         : logging.ERROR,
+        "warning"       : logging.WARNING,
+        "warn"          : logging.WARNING,
+        "info"          : logging.INFO,
+        "trace_warning" : cmpi_logging.TRACE_WARNING,
+        "trace_info"    : cmpi_logging.TRACE_INFO,
+        "trace_verbose" : cmpi_logging.TRACE_VERBOSE,
+        "debug"         : logging.DEBUG
+}
+
+class DispatchingFormatter:
+    """
+    Formatter class for logging module. It allows to predefine different
+    format string for paricular module names.
+
+    There is no way, how to setup this formatter in configuration file.
+    """
+    def __init__(self, formatters, default):
+        """
+        *format* in parameters description can be either ``string`` or
+        another formatter object.
+
+        :param formatters (``dict``) Mapping of module names to *format*.
+        :param default Default *format*.
+        """
+        for k, formatter in formatters.items():
+            if isinstance(formatter, basestring):
+                formatters[k] = logging.Formatter(formatter)
+        self._formatters = formatters
+        if isinstance(default, basestring):
+            default = logging.Formatter(default)
+        self._default_formatter = default
+
+    def format(self, record):
+        """
+        Interface for logging module.
+        """
+        formatter = self._formatters.get(record.name, self._default_formatter)
+        return formatter.format(record)
+
+# *****************************************************************************
+# Decorators
+# *****************************************************************************
+def trace_function_or_method(is_method=False, frame_level=1):
+    """
+    Factory for function and method decorators. Generated decorators
+    log every calls and exits of decorated functions or methods.
+
+    Logged information contain the caller's module and line together with
+    called function's module, function name and line number.
+
+    :param is_method: (``bool``) Whether returned decorator is targeted
+        for use upon a method of a class. It modified logged function by
+        prepending owning class name.
+    :param frame_level: (``int``) Number of nested frames to skip when
+        searching for called function scope by inspecting stack upwards.
+        When the result of this function is applied directly on the definition
+        of function, it's value should be 1. When used from inside of some
+        other factory, it must be increased by 1.
+    """
+
+    assert frame_level >= 1
+
+    def _decorator(func):
+        """
+        Decorator for logging entries and exits of function or method.
+        """
+        if not inspect.ismethod(func) and not inspect.isfunction(func):
+            raise TypeError("func must be a function")
+
+        def _print_value(val):
+            """
+            Used here for printing function arguments. Shortens the output
+            string, if that would be too long.
+            """
+            if isinstance(val, list):
+                if len(val) < 2:
+                    return str(val)
+                else:
+                    return "[%s, ...]" % _print_value(val[0])
+            return str(val)
+
+        logger = logging.getLogger(__name__+'.trace_function_or_method')
+        module = func.__module__.split('.')[-1]
+        frm = inspect.currentframe()
+        for i in range(frame_level):
+            frm = frm.f_back
+        lineno = frm.f_lineno
+        del frm
+        classname = inspect.getouterframes(
+                inspect.currentframe())[frame_level][3]
+
+        def _wrapper(self, *args, **kwargs):
+            """
+            Wrapper for function or method, that does the logging.
+            """
+            if logger.isEnabledFor(logging.DEBUG):
+                frm = inspect.currentframe()
+                logargs = {
+                    "caller_file" : os.path.basename(os.path.splitext(
+                        frm.f_back.f_code.co_filename)[0]),
+                    "caller_lineno" : frm.f_back.f_lineno,
+                    "module" : module,
+                    "func"   : classname + "." + func.__name__
+                        if is_method else func.__name__,
+                    "lineno" : lineno,
+                    "action" : "entering",
+                    "args"   : ", ".join(chain(
+                                (_print_value(a) for a in args),
+                                (   "%s=%s"%(k, _print_value(v))
+                                for k, v in kwargs.items())))
+                }
+
+                if not logargs["args"]:
+                    logargs["args"] = ""
+                else:
+                    logargs["args"] = " with args=(%s)" % logargs["args"]
+                logger.debug("%(caller_file)s:%(caller_lineno)d - %(action)s"
+                    " %(module)s:%(func)s:%(lineno)d%(args)s" , logargs)
+            try:
+                result = func(self, *args, **kwargs)
+                if logger.isEnabledFor(logging.DEBUG):
+                    logargs["action"] = "exiting"
+                    logger.debug("%(caller_file)s:%(caller_lineno)d"
+                        " - %(action)s %(module)s:%(func)s:%(lineno)d",
+                        logargs)
+            except Exception as exc:
+                if logger.isEnabledFor(logging.DEBUG):
+                    logargs['action'] = 'exiting'
+                    logargs['error'] = str(exc)
+                    logger.debug("%(caller_file)s:%(caller_lineno)d"
+                        " - %(action)s %(module)s:%(func)s:%(lineno)d"
+                        " with error: %(error)s", logargs)
+                raise
+            return result
+
+        return _wrapper
+
+    return _decorator
+
+def trace_function(func, frame_level=1):
+    """ Convenience function used for decorating simple functions. """
+    return trace_function_or_method(frame_level=frame_level + 1)(func)
+
+def trace_method(func, frame_level=1):
+    """ Convenience function used for decorating methods. """
+    return trace_function_or_method(True, frame_level + 1)(func)
+
+def setup(env, config):
+    """
+    Set up the logging with options given by SoftwareConfiguration instance.
+    This should be called at process's startup before any message is sent to
+    log.
+
+    :param env: (``ProviderEnvironment``) Provider environment, taken
+        from CIMOM callback (e.g. ``get_providers()``).
+    :param config: (``BaseConfiguration``) Configuration with Log section
+        containing settings for logging.
+    """
+    cp = config.config
+    logging_setup = False
+    try:
+        path = config.file_path('Log', 'FileConfig')
+        if not os.path.exists(path):
+            logging.getLogger(__name__).error('given FileConfig "%s" does'
+                    ' not exist', path)
+        else:
+            logging.config.fileConfig(path)
+            logging_setup = True
+    except Exception:
+        if cp.has_option('Log', 'FileConfig'):
+            logging.getLogger(__name__).exception(
+                    'failed to setup logging from FileConfig')
+    if logging_setup is False:
+        defaults = DEFAULT_LOGGING_CONFIG.copy()
+        defaults["handlers"]["cmpi"]["cmpi_logger"] = env.get_logger()
+        if config.stderr:
+            defaults["root"]["handlers"] = ["stderr"]
+        level = config.logging_level
+        if not level in LOGGING_LEVELS:
+            logging.getLogger(__name__).error(
+                    'level name "%s" not supported', level)
+        else:
+            level = LOGGING_LEVELS[level]
+            for handler in defaults["handlers"].values():
+                handler["level"] = level
+            defaults["root"]["level"] = level
+        logging.config.dictConfig(defaults)
+    # needed for shared code under lmi.common
+    cmpi_logging.logger = logging.getLogger('lmi.common')
+
+def get_logger(module_name):
+    """
+    Convenience function for getting callable returning logger for particular
+    module name. It's supposed to be used at module's level to assign its
+    result to global variable like this:
+
+        LOG = cmpi_logging.get_logger(__name__)
+
+    This can be used in module's functions and classes like this:
+
+        def module_function(param):
+            LOG().debug("this is debug statement logging param: %s", param)
+
+    Thanks to ``LOG`` being a callable, it always returns valid logger object
+    with current configuration, which may change overtime.
+    """
+    def _logger():
+        """ Callable used to obtain current logger object. """
+        return logging.getLogger(module_name)
+    return _logger
+