python: redone cmpi_logging

Module now contains enhanced tracing function decorators providing more
details. There is no global logger, each provider module should obtain
its own logger via get_logger() function.

Usage of LogManager is optional. It allows for logging's
reconfiguration, when config file is changed.

Exceptions logged with error(), exception() or critical() methods are
now logged twice:
  * First time for specified level with error message only.
  * Second time for TRACE_WARNING level with traceback.
This prevents the polution of syslog.

4 files changed, 381 insertions, 186 deletions

diff --git a/src/python/lmi/providers/IndicationManager.py b/src/python/lmi/providers/IndicationManager.py
index 0b0e132..2d3c595 100644
--- a/src/python/lmi/providers/IndicationManager.py
+++ b/src/python/lmi/providers/IndicationManager.py
@@ -40,6 +40,8 @@ FILTER_DEFAULTS = {
         "QueryLanguage"    : "CIM:CQL"
 }
 
+LOG = cmpi_logging.get_logger(__name__)
+
 @cmpi_logging.trace_function
 def enumerate_namespaces(ch):
     """
@@ -67,14 +69,14 @@ def enumerate_namespaces(ch):
                         pywbem.CIM_ERR_INVALID_CLASS):
                     pass
                 if exc[0] == pywbem.CIM_ERR_FAILED:
-                    cmpi_logging.logger.error("EnumerateInstanceNames failed"
-                            " for %s:%s: %s", ns, cls, str(exc))
+                    LOG().error("EnumerateInstanceNames failed for %s:%s: %s",
+                            ns, cls, str(exc))
                 else:
                     raise
         if nspaths:
             break
     if not nspaths:
-        cmpi_logging.logger.error("failed to enumerate namespaces")
+        LOG().error("failed to enumerate namespaces")
         ns = None
     return (nspaths, ns)
 
@@ -149,8 +151,8 @@ def remove_cimom_filter(ch, fltr_path):
         ch.DeleteInstance(ref)
         referents.append(ref)
     ch.DeleteInstance(fltr_path)
-    cmpi_logging.logger.debug('removed indication filter "%s" with %d'
-        ' referents', fltr_path["Name"], len(referents))
+    LOG().debug('removed indication filter "%s" with %d referents',
+            fltr_path["Name"], len(referents))
     return referents
 
 class IndicationManager(singletonmixin.Singleton):
@@ -331,8 +333,7 @@ class IndicationManager(singletonmixin.Singleton):
             if self._ns_interop is None:
                 ch = self._env.get_cimom_handle()
                 self._ns_interop = find_ns_interop(ch)
-                cmpi_logging.logger.info('found interop namespace: %s',
-                        self._ns_interop)
+                LOG().info('found interop namespace: %s', self._ns_interop)
             return self._ns_interop
 
     @property
@@ -389,9 +390,9 @@ class IndicationManager(singletonmixin.Singleton):
         if installed:
             for prop_name, val in self._filters[class_name][fltr_id].items():
                 if inst[prop_name] != val:
-                    cmpi_logging.logger.info("filter \"%s\" is installed, but"
-                            " its property \"%s\" has outdated value;"
-                            " removing...", fltr_id, prop_name)
+                    LOG().info("filter \"%s\" is installed, but its property"
+                            " \"%s\" has outdated value; removing...",
+                            fltr_id, prop_name)
                     referents = remove_cimom_filter(ch, inst.path)
                     installed = False
         if not installed:
@@ -408,14 +409,13 @@ class IndicationManager(singletonmixin.Singleton):
             inst.update(kwargs)
             try:
                 inst = ch.CreateInstance(inst)
-                cmpi_logging.logger.info("filter \"%s\" installed", fltr_id)
+                LOG().info("filter \"%s\" installed", fltr_id)
             except pywbem.CIMError:
-                cmpi_logging.logger.exception(
-                        "failed to install indication filter \"%s\"",
+                LOG().exception("failed to install indication filter \"%s\"",
                         fltr_id)
             if referents:
-                cmpi_logging.logger.debug('reinstalling %d filter'
-                        ' subscriptions', len(referents))
+                LOG().debug('reinstalling %d filter subscriptions',
+                        len(referents))
                 for ref in referents:
                     ch.CreateInstance(ref)
         return inst
@@ -462,11 +462,11 @@ class IndicationManager(singletonmixin.Singleton):
             try:
                 for clsname, fltr_id in filters_to_check:
                     self._ensure_cimom_has_filter(clsname, fltr_id)
-                cmpi_logging.logger.debug('filters installed')
+                LOG().debug('filters installed')
                 return True
             except pywbem.CIMError as exc:
                 if exc.args[0] == pywbem.CIM_ERR_ACCESS_DENIED:
-                    cmpi_logging.logger.error("filters could not be checked"
+                    LOG().error("filters could not be checked"
                             " for presence due to invalid context")
                     return False
                 raise
@@ -532,7 +532,7 @@ class IndicationManager(singletonmixin.Singleton):
             res = self._get_matching_filter(fltr)
             if res is not None:
                 self._subscribed_filters.add((res[0], res[1]))
-                cmpi_logging.logger.info("InstanceFilter %s: %s authorized",
+                LOG().info("InstanceFilter %s: %s authorized",
                         make_filter_name(res[0], res[1]), fltr)
                 return True
             return False
@@ -563,7 +563,7 @@ class IndicationManager(singletonmixin.Singleton):
             res = self._get_matching_filter(fltr)
             if res is not None:
                 self._subscribed_filters.add((res[0], res[1]))
-                cmpi_logging.logger.info("InstanceFilter %s: %s started",
+                LOG().info("InstanceFilter %s: %s started",
                         make_filter_name(res[0], res[1]), fltr)
 
     @cmpi_logging.trace_method
@@ -591,7 +591,7 @@ class IndicationManager(singletonmixin.Singleton):
             res = self._get_matching_filter(fltr)
             if res is not None:
                 self._subscribed_filters.remove((res[0], res[1]))
-                cmpi_logging.logger.info("InstanceFilter %s: %s stopped",
+                LOG().info("InstanceFilter %s: %s stopped",
                         make_filter_name(res[0], res[1]), fltr)
 
     @cmpi_logging.trace_method
@@ -607,7 +607,7 @@ class IndicationManager(singletonmixin.Singleton):
         """
         with self._access_lock:
             self._enabled = True
-        cmpi_logging.logger.info("Indications enabled")
+        LOG().info("Indications enabled")
 
     @cmpi_logging.trace_method
     def disable_indications(self, _env):
@@ -622,7 +622,7 @@ class IndicationManager(singletonmixin.Singleton):
         """
         with self._access_lock:
             self._enabled = False
-        cmpi_logging.logger.info("Indications disabled")
+        LOG().info("Indications disabled")
 
     @cmpi_logging.trace_method
     def send_indication(self, indication):
@@ -656,8 +656,8 @@ class IndicationManager(singletonmixin.Singleton):
                 instance.classname, filter_id)
         ind['PerceivedSeverity'] = self.SEVERITY_INFO
 
-        cmpi_logging.logger.info("Sending indication %s for %s" %
-                (ind["IndicationFilterName"], str(path)))
+        LOG().info("Sending indication %s for %s",
+                ind["IndicationFilterName"], str(path))
         self.send_indication(ind)
 
     @cmpi_logging.trace_method
@@ -688,7 +688,7 @@ class IndicationManager(singletonmixin.Singleton):
                 new_instance.classname, filter_id)
         ind['PerceivedSeverity'] = self.SEVERITY_INFO
 
-        cmpi_logging.logger.info("Sending indication %s for %s",
+        LOG().info("Sending indication %s for %s",
                 ind["IndicationFilterName"], str(path))
         self.send_indication(ind)
 
@@ -732,12 +732,12 @@ class IndicationManager(singletonmixin.Singleton):
 
             if isinstance(command, pywbem.CIMInstance) :
                 indication = command
-                cmpi_logging.logger.trace_info("Delivering indication %s" %
-                        (str(indication.path)))
+                LOG().trace_info("Delivering indication %s",
+                        str(indication.path))
                 broker.DeliverIndication(self.namespace, indication)
 
             elif isinstance(command, int):
-                cmpi_logging.logger.trace_info("Received command %d", command)
+                LOG().trace_info("Received command %d", command)
                 if command == self.COMMAND_STOP:
                     if hasattr(self._queue, "task_done"):
                         self._queue.task_done()
@@ -746,7 +746,7 @@ class IndicationManager(singletonmixin.Singleton):
             if hasattr(self._queue, "task_done"):
                 self._queue.task_done()
 
-        cmpi_logging.logger.info("Stopped Indication thread.")
+        LOG().info("Stopped Indication thread.")
 
     @cmpi_logging.trace_method
     def shutdown(self):
diff --git a/src/python/lmi/providers/JobManager.py b/src/python/lmi/providers/JobManager.py
index a0283fb..609c7db 100644
--- a/src/python/lmi/providers/JobManager.py
+++ b/src/python/lmi/providers/JobManager.py
@@ -53,6 +53,8 @@ import traceback
 from lmi.providers import cmpi_logging, parse_instance_id
 from lmi.providers.IndicationManager import IndicationManager
 
+LOG = cmpi_logging.get_logger(__name__)
+
 @cmpi_logging.trace_function
 def register_filters(job_clsname, indication_manager=None):
     """
@@ -286,8 +288,8 @@ class Job(object):
         """
         self.lock()
 
-        cmpi_logging.logger.debug("Job %s: %s changes state from %d to %d"
-                % (self.the_id, self.job_name, self.job_state, new_state))
+        LOG().debug("Job %s: %s changes state from %d to %d",
+                self.the_id, self.job_name, self.job_state, new_state)
 
         # For sending indications
         prev_instance = None
@@ -356,8 +358,7 @@ class Job(object):
         Callback when a Job completes and time_before_removal second passed.
         The job gets removed from its JobManager.
         """
-        cmpi_logging.logger.debug("Job %s: %s expired"
-                % (self.the_id, self.job_name))
+        LOG().debug("Job %s: %s expired", self.the_id, self.job_name)
 
         self.job_manager.remove_job(self)
 
@@ -385,8 +386,8 @@ class Job(object):
                 self._expire()
                 return
 
-            cmpi_logging.logger.debug("Starting timer for job %s: '%s' for %f"
-                    " seconds" % (self.the_id, self.job_name, timeout))
+            LOG().debug("Starting timer for job %s: '%s' for %f seconds",
+                    self.the_id, self.job_name, timeout)
             self.timer = self.timer_manager.create_timer(
                     "Job " + self.job_name,
                     callback=self._expire)
@@ -418,16 +419,12 @@ class Job(object):
         try:
             self._execute(*(self._execargs), **(self._execkwargs))
         except pywbem.CIMError, error:
-            cmpi_logging.logger.trace_warn("Job.execute caught an CIMError %s",
-                    str(error))
-            cmpi_logging.logger.trace_verbose("traceback: %s",
-                        traceback.format_exc())
+            LOG().trace_warn("Job.execute caught an CIMError %s", str(error))
+            LOG().trace_verbose("traceback: %s", traceback.format_exc())
             self.finish_method(Job.STATE_FAILED, error=error)
         except Exception, ex:
-            cmpi_logging.logger.trace_warn("Job.execute caught an Exception %s",
-                    str(ex))
-            cmpi_logging.logger.trace_verbose("traceback: %s",
-                        traceback.format_exc())
+            LOG().trace_warn("Job.execute caught an Exception %s", str(ex))
+            LOG().trace_verbose("traceback: %s", traceback.format_exc())
             error = pywbem.CIMError(pywbem.CIM_ERR_FAILED, str(ex))
             self.finish_method(Job.STATE_FAILED, error=error)
 
@@ -812,8 +809,7 @@ class JobManager(object):
 
         :param job: (``Job``) A job to enqueue.
         """
-        cmpi_logging.logger.debug("Job %s: '%s' enqueued"
-                % (job.the_id, job.job_name))
+        LOG().debug("Job %s: '%s' enqueued", job.the_id, job.job_name)
 
         self.jobs[job.the_id] = job
         self.queue.put(job)
@@ -847,8 +843,8 @@ class JobManager(object):
 
         :param job: (``Job``) Job to remove.
         """
-        cmpi_logging.logger.debug("Job %s: '%s' removed from queue."
-                % (job.the_id, job.job_name))
+        LOG().debug("Job %s: '%s' removed from queue.",
+                job.the_id, job.job_name)
         del self.jobs[job.the_id]
         # The job may still be in the queue!
         # There is no way, how to remove it, it will be skipped by the
@@ -878,7 +874,7 @@ class JobManager(object):
         This is the main loop of the job queue. It just processes enqueued
         jobs and never ends.
         """
-        cmpi_logging.logger.info("Started Job thread.")
+        LOG().info("Started Job thread.")
         while True:
             command = self.queue.get()
             if isinstance(command, Job):
@@ -890,16 +886,16 @@ class JobManager(object):
                     # the job was not cancelled
                     job.change_state(Job.STATE_RUNNING)
                     job.unlock()
-                    cmpi_logging.logger.info("Starting job %s: '%s'" %
-                            (job.the_id, job.job_name))
+                    LOG().info("Starting job %s: '%s'",
+                            job.the_id, job.job_name)
 
                     job.execute()
                     if job.error:
-                        cmpi_logging.logger.warn("Job %s: '%s' finished with error:"
-                                " %s" % (job.the_id, job.job_name, str(job.error)))
+                        LOG().warn("Job %s: '%s' finished with error: %s",
+                                job.the_id, job.job_name, str(job.error))
                     else:
-                        cmpi_logging.logger.info("Job %s: '%s' finished OK" %
-                                (job.the_id, job.job_name))
+                        LOG().info("Job %s: '%s' finished OK",
+                                job.the_id, job.job_name)
                 else:
                     # just skip suspended and terminated jobs
                     job.unlock()
@@ -910,7 +906,7 @@ class JobManager(object):
 
             self.queue.task_done()
 
-        cmpi_logging.logger.info("Stopped Job thread.")
+        LOG().info("Stopped Job thread.")
 
     @cmpi_logging.trace_method
     def get_next_id(self):
diff --git a/src/python/lmi/providers/TimerManager.py b/src/python/lmi/providers/TimerManager.py
index 76b2f5b..6d05bb2 100644
--- a/src/python/lmi/providers/TimerManager.py
+++ b/src/python/lmi/providers/TimerManager.py
@@ -56,6 +56,8 @@ import Queue
 from lmi.base import singletonmixin
 from lmi.providers import cmpi_logging
 
+LOG = cmpi_logging.get_logger(__name__)
+
 class TimerException(Exception):
     pass
 
@@ -114,7 +116,7 @@ class Timer(object):
         self._args = args
         self._kwargs = kwargs
 
-        cmpi_logging.logger.trace_info("Timer: Timer %s created" % name)
+        LOG().trace_info("Timer: Timer %s created", name)
 
     @cmpi_logging.trace_method
     def set_callback(self, callback, *args, **kwargs):
@@ -140,9 +142,8 @@ class Timer(object):
         self._timeout = timeout
         now = self._mgr.now()
         self._end_time = now + timeout
-        cmpi_logging.logger.trace_info(
-                "Timer: Timer %s started at %f for %f seconds"
-                % (self._name, now, self._timeout))
+        LOG().trace_info("Timer: Timer %s started at %f for %f seconds",
+                self._name, now, self._timeout)
         self._mgr._add_timer(self)
 
     @cmpi_logging.trace_method
@@ -151,8 +152,7 @@ class Timer(object):
         Cancel the timer. This method does not guarantee that the callback won't
         be called, the timer might be calling the callback right now,
         """
-        cmpi_logging.logger.trace_info("Timer: Timer %s cancelled"
-                % (self._name))
+        LOG().trace_info("Timer: Timer %s cancelled", self._name)
         self._mgr._remove_timer(self)
 
     @cmpi_logging.trace_method
@@ -164,8 +164,7 @@ class Timer(object):
         :returns: (``boolean``) ``True``, if the timer is expired.
         """
         if self._end_time <= now:
-            cmpi_logging.logger.trace_info("Timer: Timer %s has expired"
-                    % (self._name))
+            LOG().trace_info("Timer: Timer %s has expired", self._name)
             return True
         return False
 
@@ -174,8 +173,7 @@ class Timer(object):
         """
         Called when the timer expired. It calls the callback.
         """
-        cmpi_logging.logger.trace_info("Timer: Calling callback for timer %s"
-                % (self._name))
+        LOG().trace_info("Timer: Calling callback for timer %s", self._name)
         self._callback(*self._args, **self._kwargs)
 
 class TimerManager(singletonmixin.Singleton):
@@ -245,7 +243,7 @@ class TimerManager(singletonmixin.Singleton):
         """
         if broker:
             broker.AttachThread()
-        cmpi_logging.logger.info("Started Timer thread.")
+        LOG().info("Started Timer thread.")
         while True:
             self._handle_expired()
             timeout = self._find_timeout()
@@ -260,7 +258,7 @@ class TimerManager(singletonmixin.Singleton):
                 except Queue.Empty:
                     # Timeout has happened, ignore the exception.
                     pass
-        cmpi_logging.logger.info("Stopped Timer thread.")
+        LOG().info("Stopped Timer thread.")
 
     @cmpi_logging.trace_method
     def _handle_expired(self):
@@ -272,8 +270,7 @@ class TimerManager(singletonmixin.Singleton):
         # Get list of expired timers.
         with self._lock:
             now = self.now()
-            cmpi_logging.logger.trace_info(
-                    "Timer: Checking for expired, now=%f." % (now))
+            LOG().trace_info("Timer: Checking for expired, now=%f.", now)
             expired = [t for t in self._timers if t._expired(now)]
 
         # Call the callbacks (unlocked!).
@@ -284,8 +281,7 @@ class TimerManager(singletonmixin.Singleton):
         with self._lock:
             for t in expired:
                 try:
-                    cmpi_logging.logger.trace_info(
-                        "Timer: Removing %s" % (t._name))
+                    LOG().trace_info("Timer: Removing %s", t._name)
                     self._timers.remove(t)
                 except ValueError:
                     # The timer has already been removed.
@@ -304,18 +300,16 @@ class TimerManager(singletonmixin.Singleton):
         """
         with self._lock:
             if not self._timers:
-                cmpi_logging.logger.trace_info(
-                        "Timer: No timers scheduled, waiting forever.")
+                LOG().trace_info("Timer: No timers scheduled, waiting forever.")
                 return None
             closest = min(self._timers, key=lambda timer: timer._end_time)
             now = self.now()
             timeout = closest._end_time - now
             if timeout > 0:
-                cmpi_logging.logger.trace_info(
-                        "Timer: Waiting for %f seconds, now=%f."
-                        % (timeout, now))
+                LOG().trace_info("Timer: Waiting for %f seconds, now=%f.",
+                        timeout, now)
                 return timeout
-            cmpi_logging.logger.trace_info(
+            LOG().trace_info(
                     "Timer: Some timer has already expired, no waiting.")
             return 0
 
@@ -332,7 +326,7 @@ class TimerManager(singletonmixin.Singleton):
             self._timers.append(timer)
         # Wake up the timer manager thread.
         self._queue.put(self.COMMAND_RESCHEDULE)
-        cmpi_logging.logger.trace_info("Timer: Timer %s added" % (timer._name))
+        LOG().trace_info("Timer: Timer %s added", timer._name)
 
     @cmpi_logging.trace_method
     def _remove_timer(self, timer):
@@ -348,8 +342,7 @@ class TimerManager(singletonmixin.Singleton):
                 pass
         # Wake up the timer manager thread.
         self._queue.put(self.COMMAND_RESCHEDULE)
-        cmpi_logging.logger.trace_info("Timer: Timer %s removed"
-                % (timer._name))
+        LOG().trace_info("Timer: Timer %s removed", timer._name)
 
     def now(self):
         """
@@ -371,7 +364,7 @@ class TimerManager(singletonmixin.Singleton):
         self._timer_thread.join()
 
 if __name__ == "__main__":
-    cmpi_logging.logger = cmpi_logging.CMPILogger("")
+    LOG = cmpi_logging.CMPILogger("")
     import time
 
     class Env(object):
diff --git a/src/python/lmi/providers/cmpi_logging.py b/src/python/lmi/providers/cmpi_logging.py
index a97e4ab..8a1c1d7 100644
--- a/src/python/lmi/providers/cmpi_logging.py
+++ b/src/python/lmi/providers/cmpi_logging.py
@@ -17,16 +17,102 @@
 # Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301  USA
 #
 # Authors: Jan Safranek <jsafrane@redhat.com>
-
+"""
+Contains handlers and loggers specific to providers logging running
+under cimom.
+"""
 
 import logging
+import logging.config
 import inspect
-import traceback
+from itertools import chain
+import os
+import sys
 
+# Custom logging levels
 TRACE_WARNING = logging.INFO - 1
 TRACE_INFO = logging.INFO - 2
 TRACE_VERBOSE = logging.DEBUG
 
+# Mapping from level name to its number
+LOGGING_LEVELS = {
+        "critical"      : logging.CRITICAL,
+        "error"         : logging.ERROR,
+        "warning"       : logging.WARNING,
+        "warn"          : logging.WARNING,
+        "info"          : logging.INFO,
+        "trace_warning" : TRACE_WARNING,
+        "trace_info"    : TRACE_INFO,
+        "trace_verbose" : TRACE_VERBOSE,
+        "debug"         : logging.DEBUG
+}
+
+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.providers.cmpi_logging.DispatchingFormatter",
+            "formatters" : {
+                "lmi.providers.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.providers.cmpi_logging.CMPILogHandler",
+            # this must be filled with broker env logger
+            "cmpi_logger" : None,
+            "level" : "ERROR",
+            "formatter" : "default"
+            },
+        },
+    "root": {
+        "level": "ERROR",
+        "handlers" : ["cmpi"],
+        },
+    }
+
+class DispatchingFormatter(object):
+    """
+    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)
+
 class CMPILogHandler(logging.Handler):
     """
         A handler class, which sends log messages to CMPI log.
@@ -67,60 +153,183 @@ class CMPILogger(logging.getLoggerClass()):
         """ Log message with TRACE_VERBOSE severity. """
         self.log(TRACE_VERBOSE, msg, *args, **kwargs)
 
+    def _log(self, level, msg, args, exc_info=None, extra=None):
+        """
+        Overrides ``_log()`` function of basic ``Logger``. The purpose is to
+        log tracebacks with different level instead of ERROR to prevent them
+        being logged to syslog.
+        """
+        if logging._srcfile:
+            #IronPython doesn't track Python frames, so findCaller throws an
+            #exception on some versions of IronPython. We trap it here so that
+            #IronPython can use logging.
+            try:
+                fn, lno, func = self.findCaller()
+            except ValueError:
+                fn, lno, func = "(unknown file)", 0, "(unknown function)"
+        else:
+            fn, lno, func = "(unknown file)", 0, "(unknown function)"
+        if exc_info:
+            if not isinstance(exc_info, tuple):
+                exc_info = sys.exc_info()
+            record = self.makeRecord(self.name, level, fn, lno, msg, args,
+                    None, func, extra)
+            self.handle(record)
+            record = self.makeRecord(self.name, TRACE_WARNING, fn,
+                    lno, str(exc_info[1]), tuple(), exc_info, func, extra)
+        else:
+            record = self.makeRecord(self.name, level, fn, lno, msg,
+                    args, exc_info, func, extra)
+        self.handle(record)
+
 logging.setLoggerClass(CMPILogger)
 
-def trace_method(func):
-    """ Decorator, trace entry and exit for a class method. """
-    classname = inspect.getouterframes(inspect.currentframe())[1][3]
-    def helper_func(*args, **kwargs):
-        """
-	Helper function, wrapping real function by trace_method decorator.
-	"""
-        logger.log(TRACE_VERBOSE, "Entering %s.%s", classname, func.__name__)
-        try:
-            ret = func(*args, **kwargs)
-        except Exception as exc:
-            if getattr(exc, "tb_printed", False) is False:
-                logger.exception("full traceback")
-                logger.log(TRACE_VERBOSE, "traceback: %s",
-                        traceback.format_exc())
-                exc.tb_printed = True
-            logger.log(TRACE_WARNING, "%s.%s threw exception %s",
-                    classname, func.__name__, str(exc))
-            raise
-        logger.log(TRACE_VERBOSE, "Exiting %s.%s", classname, func.__name__)
-        return ret
-    helper_func.__name__ = func.__name__
-    helper_func.__doc__ = func.__doc__
-    helper_func.__module__ = func.__module__
-    return helper_func
-
-def trace_function(func):
-    """ Decorator, trace entry and exit for a function outside any class. """
-    def helper_func(*args, **kwargs):
-        """
-	Helper function, wrapping real function by trace_method decorator.
-	"""
-        logger.log(TRACE_VERBOSE, "Entering %s.%s",
-                func.__module__, func.__name__)
-        try:
-            ret = func(*args, **kwargs)
-        except Exception as exc:
-            if getattr(exc, "tb_printed", False) is False:
-                logger.exception("full traceback")
-                logger.log(TRACE_VERBOSE, "traceback: %s",
-                        traceback.format_exc())
-                exc.tb_printed = True
-            logger.log(TRACE_WARNING, "%s.%s threw exception %s",
-			func.__module__, func.__name__, str(exc))
-            raise
-        logger.log(TRACE_VERBOSE, "Exiting %s.%s",
-                func.__module__, func.__name__)
-        return ret
-    helper_func.__name__ = func.__name__
-    helper_func.__doc__ = func.__doc__
-    helper_func.__module__ = func.__module__
-    return helper_func
+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)
+
+        module = func.__module__.split('.')[-1]
+        frm = inspect.currentframe()
+        for _ in range(frame_level):
+            frm = frm.f_back
+        lineno = frm.f_lineno
+        del frm
+        classname = inspect.getouterframes(
+                inspect.currentframe())[frame_level][3]
+
+        def _wrapper(*args, **kwargs):
+            """
+            Wrapper for function or method, that does the logging.
+            """
+            logger = logging.getLogger(__name__+'.trace_function_or_method')
+            logargs = {}
+            if logger.isEnabledFor(logging.DEBUG):
+                frm = inspect.currentframe()
+                logargs.update({
+                    "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(*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)
 
 class LogManager(object):
     """
@@ -128,77 +337,74 @@ class LogManager(object):
         There should be only one instance of this class and it should be
         instantiated as soon as possible, even before reading a config.
         The config file can be provided later by set_config call.
-    """
-    FORMAT_STDERR = '%(levelname)s: %(message)s'
-    FORMAT_CMPI = '%(levelname)s: %(message)s'
 
-    LOGGER_NAME = "lmi.storage"
+        Use of this manager is an alternative to single call to ``setup()``
+        function of this module.
+    """
 
     def __init__(self, env):
         """
             Initialize logging.
         """
-        formatter = logging.Formatter(self.FORMAT_CMPI)
-
-        self.cmpi_handler = CMPILogHandler(env.get_logger())
-        self.cmpi_handler.setLevel(logging.DEBUG)
-        self.cmpi_handler.setFormatter(formatter)
-
-        self.logger = logging.getLogger(self.LOGGER_NAME)
-        self.logger.addHandler(self.cmpi_handler)
-        self.logger.setLevel(logging.INFO)
-
-        self.stderr_handler = None
-        self.config = None
+        self._env = env
+        self._config = None
 
-        global logger  # IGNORE:W0603
-        logger = self.logger
-        logger.info("CMPI log started")
-
-    @trace_method
-    def set_config(self, config):
+    @property
+    def config(self):
+        """ Provider configuration object. """
+        return self._config
+    @config.setter
+    def config(self, config):
         """
             Set a configuration of logging. It applies its setting immediately
             and also subscribes for configuration changes.
         """
-        self.config = config
+        self._config = config
         config.add_listener(self._config_changed)
         # apply the config
         self._config_changed(config)
 
+    @property
+    def cmpi_handler(self):
+        """ Returns cmpi log handler passing logged messages to cimom. """
+        for handler in logging.getLogger('').handlers:
+            if isinstance(handler, CMPILogHandler):
+                return handler
+        return CMPILogHandler(self._env.get_logger())
+
     @trace_method
     def _config_changed(self, config):
         """
             Apply changed configuration, i.e. start/stop sending to stderr
             and set appropriate log level.
         """
-        if config.tracing:
-            self.logger.setLevel(logging.DEBUG)
-        else:
-            self.logger.setLevel(logging.INFO)
-        if config.stderr:
-            # start sending to stderr
-            if not self.stderr_handler:
-                # create stderr handler
-                formatter = logging.Formatter(self.FORMAT_STDERR)
-                self.stderr_handler = logging.StreamHandler()
-                self.stderr_handler.setLevel(logging.DEBUG)
-                self.stderr_handler.setFormatter(formatter)
-                self.logger.addHandler(self.stderr_handler)
-                self.logger.info("Started logging to stderr.")
-        else:
-            # stop sending to stderr
-            if self.stderr_handler:
-                self.logger.info("Stopped logging to stderr.")
-                self.logger.removeHandler(self.stderr_handler)
-            self.stderr_handler = None
+        setup(self._env, config)
 
     def destroy(self):
-        if self.stderr_handler:
-            self.logger.removeHandler(self.stderr_handler)
-            self.stderr_handler = None
-        self.logger.removeHandler(self.cmpi_handler)
-        self.cmpi_handler = None
-        self.config.remove_listener(self._config_changed)
-
-logger = None
+        """
+            Shuts down the logging framework. No logging can be done
+            afterwards.
+        """
+        logging.getLogger(__name__).debug('shutting down logging')
+        logging.shutdown()
+
+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