diff --git a/moulinette/__init__.py b/moulinette/__init__.py index 698cda5e..8686c2c2 100755 --- a/moulinette/__init__.py +++ b/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() diff --git a/moulinette/actionsmap.py b/moulinette/actionsmap.py index 4bea8e19..b8858a4e 100644 --- a/moulinette/actionsmap.py +++ b/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(): diff --git a/moulinette/utils/__init__.py b/moulinette/utils/__init__.py new file mode 100644 index 00000000..e69de29b diff --git a/moulinette/utils/log.py b/moulinette/utils/log.py new file mode 100644 index 00000000..d4877165 --- /dev/null +++ b/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)