libervia-backend: src/core/log.py comparison

comparison src/core/log.py @ 1007:a7d33c7a8277

core (log): refactoring + twisted backend: - configuration is now done with classes, so inheritance is possible - twisted backend now use twisted log methods - log not produced by SàT directly in twisted backend are captured by an observer (twistedObserver) and sent back to SàT logging chain, with the "twisted" logger. - \\default output use normal twistd output, except in debug mode where it add an stdout output in addition to the log file. - when log_colors = True, colors are enabled only where it's possible (tty out), when log_colors=force colors are always enabled. - fixed some bad log.xxx calls

author	Goffi <goffi@goffi.org>
date	Mon, 05 May 2014 18:58:34 +0200
parents	325fd230c15d
children	d70d4fe5c5f8

comparison

equal deleted inserted replaced

-:325fd230c15d
+:a7d33c7a8277
 _backend = None
 _loggers = {}
 _handlers = {}
 class Filtered(Exception):
 pass
 class Logger(object):
 """High level logging class"""
-fmt = None
+fmt = None # format option as given by user (e.g. SAT_LOG_LOGGER)
-filter_name = None
+filter_name = None # filter to call
 post_treat = None
 def __init__(self, name):
-self._name = name
+if isinstance(name, Logger):
+self.copy(name)
+else:
+self._name = name
+def copy(self, other):
+"""Copy values from other Logger"""
+self.fmt = other.fmt
+self.Filter_name = other.fmt
+self.post_treat = other.post_treat
+self._name = other._name
+def out(self, message, level=None):
+"""Actually log the message
+@param message: formatted message
+"""
+print message
 def log(self, level, message):
 """Print message
 @param level: one of C.LOG_LEVELS
 @param message: message to format and print
 """
 try:
 formatted = self.format(level, message)
 if self.post_treat is None:
-print formatted
+self.out(formatted, level)
 else:
-print self.post_treat(level, formatted)
+self.out(self.post_treat(level, formatted), level)
 except Filtered:
 pass
 def format(self, level, message):
 """Format message according to Logger.fmt
 @param level: one of C.LOG_LEVELS
 @param message: message to format
 @return: formatted message
-@raise: Filtered the message must not be logged
+@raise: Filtered when the message must not be logged
 """
 if self.fmt is None and self.filter_name is None:
 return message
 record = {'name': self._name,
 'message': message,
 if not self.filter_name.dictFilter(record):
 raise Filtered
 except AttributeError:
 if self.filter_name is not None:
 raise ValueError("Bad filter: filters must have a .filter method")
-return self.fmt % record
+return self.fmt % record if self.fmt is not None else message
 def debug(self, msg):
 self.log(C.LOG_LVL_DEBUG, msg)
 def info(self, msg):
 def error(self, msg):
 self.log(C.LOG_LVL_ERROR, msg)
 def critical(self, msg):
 self.log(C.LOG_LVL_CRITICAL, msg)
+class TwistedLogger(Logger):
+colors = True
+force_colors = False
+def __init__(self, *args, **kwargs):
+super(TwistedLogger, self).__init__(*args, **kwargs)
+from twisted.python import log
+self.twisted_log = log
+def out(self, message, level=None):
+"""Actually log the message
+@param message: formatted message
+"""
+self.twisted_log.msg(message.encode('utf-8', 'ignore'), sat_logged=True, level=level)
 class FilterName(object):
 """Filter on logger name according to a regex"""
 C.ANSI_RESET)
 else:
 out = message
 return ''.join(out)
-def _manageOutputs(outputs_raw):
-""" Parse output option in a backend agnostic way, and fill _handlers consequently
+class Configure(object):
+LOGGER_CLASS = None
-@param outputs_raw: output option as enterred in environment variable or in configuration
-"""
+def __init__(self, level=None, fmt=None, output=None, logger=None, colors=False, force_colors=False):
-if not outputs_raw:
+"""Configure backend
-return
+@param level: one of C.LOG_LEVELS
-outputs = outputs_raw.split(C.LOG_OPT_OUTPUT_SEP)
+@param fmt: format string, pretty much as in std logging. Accept the following keywords (maybe more depending on backend):
-global _handlers
+- "message"
-if len(outputs) == 1:
+- "levelname"
-_handlers[C.LOG_OPT_OUTPUT_FILE] = outputs.pop()
+- "name" (logger name)
+@param logger: if set, use it as a regular expression to filter on logger name.
-for output in outputs:
+Use search to match expression, so ^ or $ can be necessary.
-if not output:
+@param colors: if True use ANSI colors to show log levels
-continue
+@param force_colors: if True ANSI colors are used even if stdout is not a tty
-if output[-1] == ')':
+"""
-# we have options
+self.preTreatment()
-opt_begin = output.rfind('(')
+self.configureLevel(level)
-options = output[opt_begin+1:-1]
+self.configureFormat(fmt)
-output = output[:opt_begin]
+self.configureOutput(output)
+self.configureLogger(logger)
+self.configureColors(colors, force_colors)
+self.postTreatment()
+self.updateCurrentLogger()
+def updateCurrentLogger(self):
+"""update existing logger to the class needed for this backend"""
+if self.LOGGER_CLASS is None:
+return
+for name, logger in _loggers.items():
+_loggers[name] = self.LOGGER_CLASS(logger)
+def preTreatment(self):
+pass
+def configureLevel(self, level):
+pass
+def configureFormat(self, fmt):
+pass
+def configureOutput(self, output):
+pass
+def configureLogger(self, logger):
+pass
+def configureColors(self, colors, force_colors):
+pass
+def postTreatment(self):
+pass
+def manageOutputs(self, outputs_raw):
+""" Parse output option in a backend agnostic way, and fill _handlers consequently
+@param outputs_raw: output option as enterred in environment variable or in configuration
+"""
+if not outputs_raw:
+return
+outputs = outputs_raw.split(C.LOG_OPT_OUTPUT_SEP)
+global _handlers
+if len(outputs) == 1:
+_handlers[C.LOG_OPT_OUTPUT_FILE] = [outputs.pop()]
+for output in outputs:
+if not output:
+continue
+if output[-1] == ')':
+# we have options
+opt_begin = output.rfind('(')
+options = output[opt_begin+1:-1]
+output = output[:opt_begin]
+else:
+options = None
+if output not in (C.LOG_OPT_OUTPUT_DEFAULT, C.LOG_OPT_OUTPUT_FILE, C.LOG_OPT_OUTPUT_MEMORY):
+raise ValueError(u"Invalid output [%s]" % output)
+if output == C.LOG_OPT_OUTPUT_DEFAULT:
+# no option for defaut handler
+_handlers[output] = None
+elif output == C.LOG_OPT_OUTPUT_FILE:
+if not options:
+ValueError("%(handler)s output need a path as option" % {'handler': output})
+_handlers.setdefault(output, []).append(options)
+options = None # option are parsed, we can empty them
+elif output == C.LOG_OPT_OUTPUT_MEMORY:
+# we have memory handler, option can be the len limit or None
+try:
+limit = int(options)
+options = None # option are parsed, we can empty them
+except (TypeError, ValueError):
+limit = C.LOG_OPT_OUTPUT_MEMORY_LIMIT
+_handlers[output] = limit
+if options: # we should not have unparsed options
+raise ValueError(u"options [%(options)s] are not supported for %(handler)s output" % {'options': options, 'handler': output})
+class ConfigureBasic(Configure):
+def configureLevel(self, level):
+if level is not None:
+# we deactivate methods below level
+level_idx = C.LOG_LEVELS.index(level)
+def dev_null(self, msg):
+pass
+for _level in C.LOG_LEVELS[:level_idx]:
+setattr(Logger, _level.lower(), dev_null)
+def configureFormat(self, fmt):
+if fmt is not None:
+if fmt != '%(message)s': # %(message)s is the same as None
+Logger.fmt = fmt
+def configureOutput(self, output):
+if output is not None:
+if output != C.LOG_OPT_OUTPUT_SEP + C.LOG_OPT_OUTPUT_DEFAULT:
+# TODO: manage other outputs
+raise NotImplementedError("Basic backend only manage default output yet")
+def configureLogger(self, logger):
+if logger:
+Logger.filter_name = FilterName(logger)
+def configureColors(self, colors, force_colors):
+if colors:
+import sys
+if force_colors or sys.stdout.isatty(): # FIXME: isatty should be tested on each handler, not globaly
+# we need colors
+Logger.post_treat = lambda self, level, message: _ansiColors(level, message)
+elif force_colors:
+raise ValueError("force_colors can't be used if colors is False")
+class ConfigureTwisted(ConfigureBasic):
+LOGGER_CLASS = TwistedLogger
+def changeObserver(self, observer, can_color=False):
+"""Install a hook on observer to manage SàT specificities
+@param observer: original observer to hook
+@param can_color: True if observer can display ansi colors
+"""
+def observer_hook(event):
+"""redirect non SàT log to twisted_logger, and add colors when possible"""
+if 'sat_logged' in event: # we only want our own logs, other are managed by twistedObserver
+# we add colors if possible
+if (can_color and self.LOGGER_CLASS.colors) or self.LOGGER_CLASS.force_colors:
+message = event.get('message', tuple())
+level = event.get('level', C.LOG_LVL_INFO)
+if message:
+event['message'] = (_ansiColors(level, ''.join(message)),) # must be a tuple
+observer(event) # we can now call the original observer
+return observer_hook
+def changeFileLogObserver(self, observer):
+"""Install SàT hook for FileLogObserver
+if the output is a tty, we allow colors, else we don't
+@param observer: original observer to hook
+"""
+log_obs = observer.__self__
+log_file = log_obs.write.__self__
+try:
+can_color = log_file.isatty()
+except AttributeError:
+can_color = False
+return self.changeObserver(observer, can_color=can_color)
+def installObserverHook(self, observer):
+"""Check observer type and install SàT hook when possible
+@param observer: observer to hook
+@return: hooked observer or original one
+"""
+if hasattr(observer, '__self__'):
+ori = observer
+if isinstance(observer.__self__, self.log.FileLogObserver):
+observer = self.changeFileLogObserver(observer)
+elif isinstance(observer.__self__, self.log.DefaultObserver):
+observer = self.changeObserver(observer, can_color=True)
+else:
+# we use print because log system is not fully initialized
+print("Unmanaged observer [%s]" % observer)
+return observer
+self.observers[ori] = observer
+return observer
+def preTreatment(self):
+"""initialise needed attributes, and install observers hooks"""
+self.observers = {}
+from twisted.python import log
+self.log = log
+self.log_publisher = log.msg.__self__
+def addObserverObserver(self_logpub, other):
+"""Install hook so we know when a new observer is added"""
+other = self.installObserverHook(other)
+return self_logpub._originalAddObserver(other)
+def removeObserverObserver(self_logpub, ori):
+"""removeObserver hook fix
+As we wrap the original observer, the original removeObserver may want to remove the original object instead of the wrapper, this method fix this
+"""
+if ori in self.observers:
+self_logpub._originalRemoveObserver(self.observers[ori])
+else:
+try:
+self_logpub._originalRemoveObserver(ori)
+except ValueError:
+try:
+ori in self.cleared_observers
+except AttributeError:
+raise ValueError("Unknown observer")
+# we replace addObserver/removeObserver by our own
+log.LogPublisher._originalAddObserver = log.LogPublisher.addObserver
+log.LogPublisher._originalRemoveObserver = log.LogPublisher.removeObserver
+import types # see https://stackoverflow.com/a/4267590 (thx Chris Morgan/aaronasterling)
+log.addObserver = types.MethodType(addObserverObserver, self.log_publisher, log.LogPublisher)
+log.removeObserver = types.MethodType(removeObserverObserver, self.log_publisher, log.LogPublisher)
+# we now change existing observers
+for idx, observer in enumerate(self.log_publisher.observers):
+self.log_publisher.observers[idx] = self.installObserverHook(observer)
+def configureLevel(self, level):
+self.LOGGER_CLASS.level = level
+super(ConfigureTwisted, self).configureLevel(level)
+def configureOutput(self, output):
+import sys
+if output is None:
+output = C.LOG_OPT_OUTPUT_SEP + C.LOG_OPT_OUTPUT_DEFAULT
+self.manageOutputs(output)
+addObserver = self.log.addObserver
+if C.LOG_OPT_OUTPUT_DEFAULT in _handlers:
+# default output is already managed, we just add output to stdout if we are in debug mode
+from twisted.internet import defer
+if defer.Deferred.debug:
+addObserver(self.log.FileLogObserver(sys.stdout).emit)
 else:
-options = None
+# \\default is not in the output, so we remove current observers
+self.cleared_observers = self.log_publisher.observers
-if output not in (C.LOG_OPT_OUTPUT_DEFAULT, C.LOG_OPT_OUTPUT_FILE, C.LOG_OPT_OUTPUT_MEMORY):
+self.observers.clear()
-raise ValueError(u"Invalid output [%s]" % output)
+del self.log_publisher.observers[:]
+# and we forbid twistd to add any observer
-if output == C.LOG_OPT_OUTPUT_DEFAULT:
+self.log.addObserver = lambda other: None
-# no option for defaut handler
-_handlers[output] = None
+if C.LOG_OPT_OUTPUT_FILE in _handlers:
-elif output == C.LOG_OPT_OUTPUT_FILE:
+from twisted.python import logfile
-if not options:
+for path in _handlers[C.LOG_OPT_OUTPUT_FILE]:
-ValueError("%(handler)s output need a path as option" % {'handler': output})
+log_file = sys.stdout if path == '-' else logfile.LogFile.fromFullPath(path)
-_handlers[output] = options
+addObserver(self.log.FileLogObserver(log_file).emit)
-options = None # option are parsed, we can empty them
-elif output == C.LOG_OPT_OUTPUT_MEMORY:
+if C.LOG_OPT_OUTPUT_MEMORY in _handlers:
-# we have memory handler, option can be the len limit or None
+raise NotImplementedError("Memory observer is not implemented in Twisted backend")
-try:
-limit = int(options)
+def configureColors(self, colors, force_colors):
-options = None # option are parsed, we can empty them
+self.LOGGER_CLASS.colors = colors
-except (TypeError, ValueError):
+self.LOGGER_CLASS.force_colors = force_colors
-limit = C.LOG_OPT_OUTPUT_MEMORY_LIMIT
+if force_colors and not colors:
-_handlers[output] = limit
+raise ValueError('colors must be True if force_colors is True')
-if options: # we should not have unparsed options
+def postTreatment(self):
-raise ValueError(u"options [%(options)s] are not supported for %(handler)s output" % {'options': options, 'handler': output})
+"""Install twistedObserver which manage non SàT logs"""
+def twistedObserver(event):
-def _configureStdLogging(logging, level=None, fmt=C.LOG_OPT_FORMAT[1], output=C.LOG_OPT_OUTPUT[1], logger=None, colors=False, force_colors=False):
+"""Observer which redirect log message not produced by SàT to SàT logging system"""
-"""Configure standard logging module
+if not 'sat_logged' in event:
+# this log was not produced by SàT
-@param logging: standard logging module
+from twisted.python import log
-@param level: one of C.LOG_LEVELS
+text = log.textFromEventDict(event)
-@param fmt: format string, pretty much as in std logging. Accept the following keywords (maybe more depending on backend):
+if text is None:
-- "message"
+return
-- "levelname"
+twisted_logger = getLogger(C.LOG_TWISTED_LOGGER)
-- "name" (logger name)
+log_method = twisted_logger.error if event.get('isError', False) else twisted_logger.info
-@param logger: if set, use it as a regular expression to filter on logger name.
+log_method(text.decode('utf-8'))
-Use search to match expression, so ^ or $ can be necessary.
-@param colors: if True use ANSI colors to show log levels
+self.log_publisher._originalAddObserver(twistedObserver)
-@param force_colors: if True ANSI colors are used even if stdout is not a tty
-"""
-format_ = fmt
+class ConfigureStandard(Configure):
-if level is None:
-level = C.LOG_LVL_DEBUG
+def __init__(self, level=None, fmt=C.LOG_OPT_FORMAT[1], output=C.LOG_OPT_OUTPUT[1], logger=None, colors=False, force_colors=False):
-import sys
+super(ConfigureStandard, self).__init__(level, fmt, output, logger, colors, force_colors)
-with_color = colors & (sys.stdout.isatty() or force_colors)
-if not colors and force_colors:
+def preTreatment(self):
-raise ValueError("force_colors can't be used if colors is False")
+"""We use logging methods directly, instead of using Logger"""
+global getLogger
-class SatFormatter(logging.Formatter):
+global debug
-u"""Formatter which manage SàT specificities"""
+global info
+global warning
-def __init__(self, fmt=None, datefmt=None):
+global error
-super(SatFormatter, self).__init__(fmt, datefmt)
+global critical
+import logging
-def format(self, record):
+getLogger = logging.getLogger
-s = super(SatFormatter, self).format(record)
+debug = logging.debug
-if with_color:
+info = logging.info
-s = _ansiColors(record.levelname, s)
+warning = logging.warning
-return s
+error = logging.error
+critical = logging.critical
-root_logger = logging.getLogger()
-if len(root_logger.handlers) == 0:
+def configureLevel(self, level):
-_manageOutputs(output)
+if level is None:
-formatter = SatFormatter(format_)
+level = C.LOG_LVL_DEBUG
-name_filter = FilterName(logger) if logger else None
+self.level = level
-for handler, options in _handlers.items():
-if handler == C.LOG_OPT_OUTPUT_DEFAULT:
+def configureFormat(self, fmt):
-hdlr = logging.StreamHandler()
+import logging
-elif handler == C.LOG_OPT_OUTPUT_MEMORY:
+format_ = fmt
-import logging.handlers
-hdlr = logging.handlers.BufferingHandler(options)
+class SatFormatter(logging.Formatter):
-_handlers[handler] = hdlr # we keep a reference to the handler to read the buffer later
+u"""Formatter which manage SàT specificities"""
-elif handler == C.LOG_OPT_OUTPUT_FILE:
-import os.path
+def __init__(self, fmt=None, datefmt=None):
-hdlr = logging.FileHandler(os.path.expanduser(options))
+super(SatFormatter, self).__init__(fmt, datefmt)
-else:
-raise ValueError("Unknown handler type")
+def format(self, record):
-hdlr.setFormatter(formatter)
+s = super(SatFormatter, self).format(record)
-root_logger.addHandler(hdlr)
+if self.with_color:
-root_logger.setLevel(level)
+s = _ansiColors(record.levelname, s)
-if name_filter is not None:
+return s
-hdlr.addFilter(name_filter)
-else:
+self.formatter = SatFormatter(format_)
-root_logger.warning(u"Handlers already set on root logger")
+def configureOutput(self, output):
-def _configureBasic(level=None, fmt=None, output=None, logger=None, colors=False, force_colors=False):
+self.manageOutputs(output)
-"""Configure basic backend
-@param level: same as _configureStdLogging.level
+def configureLogger(self, logger):
-@param fmt: same as _configureStdLogging.fmt
+self.name_filter = FilterName(logger) if logger else None
-@param output: not implemented yet TODO
-@param logger: same as _configureStdLogging.logger
+def configureColors(self, colors, force_colors):
-@param colors: same as _configureStdLogging.colors
-@param force_colors: same as _configureStdLogging.force_colors
-"""
-if level is not None:
-# we deactivate methods below level
-level_idx = C.LOG_LEVELS.index(level)
-def dev_null(self, msg):
-pass
-for _level in C.LOG_LEVELS[:level_idx]:
-setattr(Logger, _level.lower(), dev_null)
-if fmt is not None:
-if fmt != '%(message)s': # %(message)s is the same as None
-Logger.fmt = fmt
-if output is not None:
-if output != C.LOG_OPT_OUTPUT_SEP + C.LOG_OPT_OUTPUT_DEFAULT:
-# TODO: manage other outputs
-raise NotImplementedError("Basic backend only manage default output yet")
-if logger:
-Logger.filter_name = FilterName(logger)
-if colors:
 import sys
-if force_colors or sys.stdout.isatty():
+self.with_color = colors & (sys.stdout.isatty() or force_colors)
-# we need colors
+if not colors and force_colors:
-Logger.post_treat = lambda self, level, message: _ansiColors(level, message)
+raise ValueError("force_colors can't be used if colors is False")
-elif force_colors:
-raise ValueError("force_colors can't be used if colors is False")
+def _addHandler(self, root_logger, hdlr):
+hdlr.setFormatter(self.formatter)
+root_logger.addHandler(hdlr)
+root_logger.setLevel(self.level)
+if self.name_filter is not None:
+hdlr.addFilter(self.name_filter)
+def postTreatment(self):
+import logging
+root_logger = logging.getLogger()
+if len(root_logger.handlers) == 0:
+for handler, options in _handlers.items():
+if handler == C.LOG_OPT_OUTPUT_DEFAULT:
+hdlr = logging.StreamHandler()
+self._addHandler(root_logger, hdlr)
+elif handler == C.LOG_OPT_OUTPUT_MEMORY:
+import logging.handlers
+hdlr = logging.handlers.BufferingHandler(options)
+_handlers[handler] = hdlr # we keep a reference to the handler to read the buffer later
+self._addHandler(root_logger, hdlr)
+elif handler == C.LOG_OPT_OUTPUT_FILE:
+import os.path
+for path in options:
+hdlr = logging.FileHandler(os.path.expanduser(path))
+self._addHandler(root_logger, hdlr)
+else:
+raise ValueError("Unknown handler type")
+else:
+root_logger.warning(u"Handlers already set on root logger")
 def configure(backend=C.LOG_BACKEND_STANDARD, **options):
 """Configure logging behaviour
 @param backend: can be:
 C.LOG_BACKEND_STANDARD: use standard logging module
 global _backend
 if _backend is not None:
 raise exceptions.InternalError("Logging can only be configured once")
 _backend = backend
-if backend in (C.LOG_BACKEND_TWISTED, C.LOG_BACKEND_STANDARD):
+if backend == C.LOG_BACKEND_BASIC:
-if backend ==  C.LOG_BACKEND_TWISTED:
+ConfigureBasic(**options)
-from twisted.python import log
-observer = log.PythonLoggingObserver()
+elif backend == C.LOG_BACKEND_TWISTED:
-observer.start()
+ConfigureTwisted(**options)
-global getLogger
-global debug
+elif backend == C.LOG_BACKEND_STANDARD:
-global info
+ConfigureStandard(**options)
-global warning
-global error
-global critical
-import logging
-_configureStdLogging(logging, **options)
-getLogger = logging.getLogger
-debug = logging.debug
-info = logging.info
-warning = logging.warning
-error = logging.error
-critical = logging.critical
-elif backend == C.LOG_BACKEND_BASIC:
-_configureBasic(**options)
 else:
 raise ValueError("unknown backend")
 def _parseOptions(options):
 _parseOptions(log_conf)
 configure(backend, **log_conf)
 def getLogger(name=C.LOG_BASE_LOGGER):
-return _loggers.setdefault(name, Logger(name))
+if _backend in (None, C.LOG_BACKEND_BASIC):
+logger_class = Logger
+elif _backend == C.LOG_BACKEND_TWISTED:
+logger_class = TwistedLogger
+else:
+raise ValueError("This method should not be called with backend [%s]" % _backend)
+return _loggers.setdefault(name, logger_class(name))
 _root_logger = getLogger()
 def debug(msg):
 _root_logger.debug(msg)

Mercurial > libervia-backend

comparison src/core/log.py @ 1007:a7d33c7a8277