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
This commit is contained in:
Goffi 2014-05-05 18:58:34 +02:00
commit ba103161d5
5 changed files with 424 additions and 164 deletions

View file

@ -78,6 +78,7 @@ class Const(object):
LOG_BACKEND_TWISTED = 'twisted'
LOG_BACKEND_BASIC = 'basic'
LOG_BASE_LOGGER = 'root'
LOG_TWISTED_LOGGER = 'twisted'
LOG_OPT_PREFIX = 'log_'
# (option_name, default_value) tuples
LOG_OPT_COLORS = ('colors', 'true') # true for auto colors, force to have colors even if stdout is not a tty, false for no color

View file

@ -27,17 +27,36 @@ _backend = None
_loggers = {}
_handlers = {}
class Filtered(Exception):
pass
class Logger(object):
"""High level logging class"""
fmt = None
filter_name = None
fmt = None # format option as given by user (e.g. SAT_LOG_LOGGER)
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
@ -48,9 +67,9 @@ class Logger(object):
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
@ -61,7 +80,7 @@ class Logger(object):
@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
@ -75,7 +94,7 @@ class Logger(object):
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)
@ -93,6 +112,23 @@ class Logger(object):
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"""
@ -152,145 +188,376 @@ def _ansiColors(level, message):
out = message
return ''.join(out)
def _manageOutputs(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()
class Configure(object):
LOGGER_CLASS = None
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
def __init__(self, level=None, fmt=None, output=None, logger=None, colors=False, force_colors=False):
"""Configure backend
@param level: one of C.LOG_LEVELS
@param fmt: format string, pretty much as in std logging. Accept the following keywords (maybe more depending on backend):
- "message"
- "levelname"
- "name" (logger name)
@param logger: if set, use it as a regular expression to filter on logger name.
Use search to match expression, so ^ or $ can be necessary.
@param colors: if True use ANSI colors to show log levels
@param force_colors: if True ANSI colors are used even if stdout is not a tty
"""
self.preTreatment()
self.configureLevel(level)
self.configureFormat(fmt)
self.configureOutput(output)
self.configureLogger(logger)
self.configureColors(colors, force_colors)
self.postTreatment()
self.updateCurrentLogger()
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)
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)
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[output] = 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
def preTreatment(self):
pass
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})
def configureLevel(self, level):
pass
def _configureStdLogging(logging, level=None, fmt=C.LOG_OPT_FORMAT[1], output=C.LOG_OPT_OUTPUT[1], logger=None, colors=False, force_colors=False):
"""Configure standard logging module
def configureFormat(self, fmt):
pass
@param logging: standard logging module
@param level: one of C.LOG_LEVELS
@param fmt: format string, pretty much as in std logging. Accept the following keywords (maybe more depending on backend):
- "message"
- "levelname"
- "name" (logger name)
@param logger: if set, use it as a regular expression to filter on logger name.
Use search to match expression, so ^ or $ can be necessary.
@param colors: if True use ANSI colors to show log levels
@param force_colors: if True ANSI colors are used even if stdout is not a tty
"""
format_ = fmt
if level is None:
level = C.LOG_LVL_DEBUG
import sys
with_color = colors & (sys.stdout.isatty() or force_colors)
if not colors and force_colors:
raise ValueError("force_colors can't be used if colors is False")
def configureOutput(self, output):
pass
class SatFormatter(logging.Formatter):
u"""Formatter which manage SàT specificities"""
def configureLogger(self, logger):
pass
def __init__(self, fmt=None, datefmt=None):
super(SatFormatter, self).__init__(fmt, datefmt)
def configureColors(self, colors, force_colors):
pass
def format(self, record):
s = super(SatFormatter, self).format(record)
if with_color:
s = _ansiColors(record.levelname, s)
return s
def postTreatment(self):
pass
root_logger = logging.getLogger()
if len(root_logger.handlers) == 0:
_manageOutputs(output)
formatter = SatFormatter(format_)
name_filter = FilterName(logger) if logger else None
for handler, options in _handlers.items():
if handler == C.LOG_OPT_OUTPUT_DEFAULT:
hdlr = logging.StreamHandler()
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
elif handler == C.LOG_OPT_OUTPUT_FILE:
import os.path
hdlr = logging.FileHandler(os.path.expanduser(options))
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:
raise ValueError("Unknown handler type")
hdlr.setFormatter(formatter)
root_logger.addHandler(hdlr)
root_logger.setLevel(level)
if name_filter is not None:
hdlr.addFilter(name_filter)
else:
root_logger.warning(u"Handlers already set on root logger")
options = None
def _configureBasic(level=None, fmt=None, output=None, logger=None, colors=False, force_colors=False):
"""Configure basic backend
@param level: same as _configureStdLogging.level
@param fmt: same as _configureStdLogging.fmt
@param output: not implemented yet TODO
@param logger: same as _configureStdLogging.logger
@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 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 logger:
Logger.filter_name = FilterName(logger)
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 colors:
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 force_colors or sys.stdout.isatty():
# 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")
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:
# \\default is not in the output, so we remove current observers
self.cleared_observers = self.log_publisher.observers
self.observers.clear()
del self.log_publisher.observers[:]
# and we forbid twistd to add any observer
self.log.addObserver = lambda other: None
if C.LOG_OPT_OUTPUT_FILE in _handlers:
from twisted.python import logfile
for path in _handlers[C.LOG_OPT_OUTPUT_FILE]:
log_file = sys.stdout if path == '-' else logfile.LogFile.fromFullPath(path)
addObserver(self.log.FileLogObserver(log_file).emit)
if C.LOG_OPT_OUTPUT_MEMORY in _handlers:
raise NotImplementedError("Memory observer is not implemented in Twisted backend")
def configureColors(self, colors, force_colors):
self.LOGGER_CLASS.colors = colors
self.LOGGER_CLASS.force_colors = force_colors
if force_colors and not colors:
raise ValueError('colors must be True if force_colors is True')
def postTreatment(self):
"""Install twistedObserver which manage non SàT logs"""
def twistedObserver(event):
"""Observer which redirect log message not produced by SàT to SàT logging system"""
if not 'sat_logged' in event:
# this log was not produced by SàT
from twisted.python import log
text = log.textFromEventDict(event)
if text is None:
return
twisted_logger = getLogger(C.LOG_TWISTED_LOGGER)
log_method = twisted_logger.error if event.get('isError', False) else twisted_logger.info
log_method(text.decode('utf-8'))
self.log_publisher._originalAddObserver(twistedObserver)
class ConfigureStandard(Configure):
def __init__(self, level=None, fmt=C.LOG_OPT_FORMAT[1], output=C.LOG_OPT_OUTPUT[1], logger=None, colors=False, force_colors=False):
super(ConfigureStandard, self).__init__(level, fmt, output, logger, colors, force_colors)
def preTreatment(self):
"""We use logging methods directly, instead of using Logger"""
global getLogger
global debug
global info
global warning
global error
global critical
import logging
getLogger = logging.getLogger
debug = logging.debug
info = logging.info
warning = logging.warning
error = logging.error
critical = logging.critical
def configureLevel(self, level):
if level is None:
level = C.LOG_LVL_DEBUG
self.level = level
def configureFormat(self, fmt):
import logging
format_ = fmt
class SatFormatter(logging.Formatter):
u"""Formatter which manage SàT specificities"""
def __init__(self, fmt=None, datefmt=None):
super(SatFormatter, self).__init__(fmt, datefmt)
def format(self, record):
s = super(SatFormatter, self).format(record)
if self.with_color:
s = _ansiColors(record.levelname, s)
return s
self.formatter = SatFormatter(format_)
def configureOutput(self, output):
self.manageOutputs(output)
def configureLogger(self, logger):
self.name_filter = FilterName(logger) if logger else None
def configureColors(self, colors, force_colors):
import sys
self.with_color = colors & (sys.stdout.isatty() or force_colors)
if not colors and 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
@ -304,28 +571,14 @@ def configure(backend=C.LOG_BACKEND_STANDARD, **options):
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_TWISTED:
from twisted.python import log
observer = log.PythonLoggingObserver()
observer.start()
global getLogger
global debug
global info
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
if backend == C.LOG_BACKEND_BASIC:
ConfigureBasic(**options)
elif backend == C.LOG_BACKEND_BASIC:
_configureBasic(**options)
elif backend == C.LOG_BACKEND_TWISTED:
ConfigureTwisted(**options)
elif backend == C.LOG_BACKEND_STANDARD:
ConfigureStandard(**options)
else:
raise ValueError("unknown backend")
@ -375,7 +628,13 @@ def satConfigure(backend=C.LOG_BACKEND_TWISTED):
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()

View file

@ -325,7 +325,7 @@ class SAT(service.Service):
#self.connect()
def stopService(self):
log.info("Salut aussi à Rantanplan")
log.info(u"Salut aussi à Rantanplan")
def run(self):
log.debug(_("running app"))

View file

@ -326,7 +326,7 @@ class Memory(object):
if "presence" in self._entities_cache[profile][entity]:
entities_presence[entity] = self._entities_cache[profile][entity]["presence"]
log.debug("Memory getPresenceStatus (%s)", entities_presence)
log.debug("Memory getPresenceStatus (%s)" % entities_presence)
return entities_presence
def setPresenceStatus(self, entity_jid, show, priority, statuses, profile_key):

View file

@ -507,7 +507,7 @@ class SatMUCClient (muc.MUCClient):
self.userLeftRoom(room, user)
def receivedGroupChat(self, room, user, body):
log.debug('receivedGroupChat: room=%s user=%s body=%s', room, user, body)
log.debug('receivedGroupChat: room=%s user=%s body=%s' % (room, user, body))
def userJoinedRoom(self, room, user):
if user.nick in self.__changing_nicks: