# HG changeset patch # User Goffi # Date 1399309114 -7200 # Node ID a7d33c7a8277fa51bc61f6875df6324e91a83ae1 # Parent 325fd230c15d31f5d63b92c7ecea4f487a1d4ec1 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 diff -r 325fd230c15d -r a7d33c7a8277 src/core/constants.py --- a/src/core/constants.py Mon May 05 18:58:34 2014 +0200 +++ b/src/core/constants.py Mon May 05 18:58:34 2014 +0200 @@ -78,6 +78,7 @@ 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 diff -r 325fd230c15d -r a7d33c7a8277 src/core/log.py --- a/src/core/log.py Mon May 05 18:58:34 2014 +0200 +++ b/src/core/log.py Mon May 05 18:58:34 2014 +0200 @@ -27,17 +27,36 @@ _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 @@ 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 @@ @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 @@ 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 @@ 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 @@ 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 - """ - 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() + 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() + + 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 - 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 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 - 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) + @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[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) + 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 - except (TypeError, ValueError): - limit = C.LOG_OPT_OUTPUT_MEMORY_LIMIT - _handlers[output] = limit + 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}) + - 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 _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 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 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") + @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 - 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 with_color: - s = _ansiColors(record.levelname, s) - return s + @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 - 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 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: - 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") + 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: + # \\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 _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") + 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_) - if logger: - Logger.filter_name = FilterName(logger) + def configureOutput(self, output): + self.manageOutputs(output) - if colors: + def configureLogger(self, logger): + self.name_filter = FilterName(logger) if logger else None + + def configureColors(self, colors, force_colors): 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") + 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 @@ 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 @@ 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() diff -r 325fd230c15d -r a7d33c7a8277 src/core/sat_main.py --- a/src/core/sat_main.py Mon May 05 18:58:34 2014 +0200 +++ b/src/core/sat_main.py Mon May 05 18:58:34 2014 +0200 @@ -325,7 +325,7 @@ #self.connect() def stopService(self): - log.info("Salut aussi à Rantanplan") + log.info(u"Salut aussi à Rantanplan") def run(self): log.debug(_("running app")) diff -r 325fd230c15d -r a7d33c7a8277 src/memory/memory.py --- a/src/memory/memory.py Mon May 05 18:58:34 2014 +0200 +++ b/src/memory/memory.py Mon May 05 18:58:34 2014 +0200 @@ -326,7 +326,7 @@ 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): diff -r 325fd230c15d -r a7d33c7a8277 src/plugins/plugin_xep_0045.py --- a/src/plugins/plugin_xep_0045.py Mon May 05 18:58:34 2014 +0200 +++ b/src/plugins/plugin_xep_0045.py Mon May 05 18:58:34 2014 +0200 @@ -507,7 +507,7 @@ 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: