[enh] Implement logging facilities and initialize it (fix #112)

moulinette/__init__.py

@@ -34,7 +34,7 @@ from moulinette.core import init_interface, MoulinetteError
 
 ## Package functions
 
-def init(**kwargs):
+def init(logging_config=None, **kwargs):
     """Package initialization
 
     Initialize directories and global variables. It must be called
@@ -42,6 +42,7 @@ def init(**kwargs):
     functions.
 
     Keyword arguments:
+        - logging_config -- A dict containing logging configuration to load
         - **kwargs -- See core.Package
 
     At the end, the global variable 'pkg' will contain a Package
@@ -53,6 +54,11 @@ def init(**kwargs):
     from moulinette.core import (
         Package, Moulinette18n, MoulinetteSignals
     )
+    from moulinette.utils.log import configure_logging
+
+    configure_logging(logging_config)
+
+    # Define and instantiate global objects
     __builtin__.__dict__['pkg'] = Package(**kwargs)
     __builtin__.__dict__['m18n'] = Moulinette18n(pkg)
     __builtin__.__dict__['msignals'] = MoulinetteSignals()

moulinette/actionsmap.py

@@ -6,13 +6,17 @@ import errno
 import logging
 import yaml
 import cPickle as pickle
+from time import time
 from collections import OrderedDict
 
 from moulinette.core import (MoulinetteError, MoulinetteLock)
 from moulinette.interfaces import BaseActionsMapParser
+from moulinette.utils.log import start_action_logging
 
 GLOBAL_ARGUMENT = '_global'
 
+logger = logging.getLogger('moulinette.actionsmap')
+
 
 ## Extra parameters ----------------------------------------------------
 
@@ -423,9 +427,19 @@ class ActionsMap(object):
                 raise ImportError("Unable to load function %s.%s/%s"
                         % (namespace, category, func_name))
             else:
+                log_id = start_action_logging()
+                logger.info('processing action [%s]: %s.%s.%s with args=%s',
+                            log_id, namespace, category, action, arguments)
+
                 # Load translation and process the action
                 m18n.load_namespace(namespace)
-                return func(**arguments)
+                start = time()
+                try:
+                    return func(**arguments)
+                finally:
+                    stop = time()
+                    logger.debug('action [%s] ended after %.3fs',
+                                 log_id, stop - start)
 
     @staticmethod
     def get_namespaces():

moulinette/utils/log.py

@@ -0,0 +1,106 @@
+import os
+import logging
+
+
+# Global configuration and functions -----------------------------------
+
+DEFAULT_LOGGING = {
+    'version': 1,
+    'disable_existing_loggers': False,
+    'formatters': {
+        'simple': {
+            'format': '%(asctime)-15s %(levelname)-8s %(name)s - %(message)s'
+        },
+    },
+    'handlers': {
+        'console': {
+            'level': 'DEBUG',
+            'formatter': 'simple',
+            'class': 'logging.StreamHandler',
+            'stream': 'ext://sys.stdout',
+        },
+    },
+    'loggers': {
+        'moulinette': {
+            'level': 'DEBUG',
+            'handlers': ['console'],
+        },
+    },
+}
+
+def configure_logging(logging_config=None):
+    """Configure logging with default and optionally given configuration
+
+    Keyword arguments:
+        - logging_config -- A dict containing logging configuration
+
+    """
+    from logging.config import dictConfig
+
+    dictConfig(DEFAULT_LOGGING)
+    if logging_config:
+        dictConfig(logging_config)
+
+
+# Action logging -------------------------------------------------------
+
+pid = os.getpid()
+action_id = 0
+
+def _get_action_id():
+    return '%d.%d' % (pid, action_id)
+
+def start_action_logging():
+    """Configure logging for a new action
+
+    Returns:
+        The new action id
+
+    """
+    global action_id
+    action_id += 1
+
+    return _get_action_id()
+
+class ActionLoggerAdapter(logging.LoggerAdapter):
+    """Adapter for action loggers
+
+    Extend an action logging output by processing both the logging message and the
+    contextual information. The action id is prepended to the message and the
+    following keyword arguments are added:
+        - action_id -- the current action id
+
+    """
+    def process(self, msg, kwargs):
+        """Process the logging call for the action
+
+        Process the logging call by retrieving the action id and prepending it to
+        the log message. It will also be added to the 'extra' keyword argument.
+
+        """
+        try:
+            action_id = self.extra['action_id']
+        except KeyError:
+            action_id = _get_action_id()
+
+        # Extend current extra keyword argument
+        extra = kwargs.get('extra', {})
+        extra['action_id'] = action_id
+        kwargs['extra'] = extra
+
+        return '[{:s}] {:s}'.format(action_id, msg), kwargs
+
+def getActionLogger(name=None, logger=None, action_id=None):
+    """Get the logger adapter for an action
+
+    Return an action logger adapter with the specified name or logger and
+    optionally for a given action id, creating it if necessary.
+
+    Either a name or a logger must be specified.
+    
+    """
+    if not name and not logger:
+        raise ValueError('Either a name or a logger must be specified')
+
+    extra = {'action_id': action_id} if action_id else {}
+    return ActionLoggerAdapter(logger or logging.getLogger(name), extra)