# -*- test-case-name: twext.python.test.test_log-*- ## # Copyright (c) 2006-2015 Apple Inc. All rights reserved. # # Licensed under the Apache License, Version 2.0 (the "License"); # you may not use this file except in compliance with the License. # You may obtain a copy of the License at # # http://www.apache.org/licenses/LICENSE-2.0 # # Unless required by applicable law or agreed to in writing, software # distributed under the License is distributed on an "AS IS" BASIS, # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. ## """ Classes and functions to do granular logging. Example usage in a module C{some.module}:: from twext.python.log import Logger log = Logger() def handleData(data): log.debug("Got data: {data!r}.", data=data) Or in a class:: from twext.python.log import Logger class Foo(object): log = Logger() def oops(self, data): self.log.error("Oops! Invalid data from server: {data!r}", data=data) C{Logger}s have namespaces, for which logging can be configured independently. Namespaces may be specified by passing in a C{namespace} argument to L{Logger} when instantiating it, but if none is given, the logger will derive its own namespace by using the module name of the callable that instantiated it, or, in the case of a class, by using the fully qualified name of the class. In the first example above, the namespace would be C{some.module}, and in the second example, it would be C{some.module.Foo}. """ __all__ = [ "InvalidLogLevelError", "LogLevel", "formatEvent", "Logger", "LegacyLogger", "ILogObserver", "LogPublisher", "PredicateResult", "ILogFilterPredicate", "FilteringLogObserver", "LogLevelFilterPredicate", "LegacyLogObserver", "replaceTwistedLoggers", ] import sys from sys import stdout, stderr from string import Formatter import inspect import logging import time from zope.interface import Interface, implementer from twisted.python.constants import NamedConstant, Names from twisted.python.failure import Failure from twisted.python.reflect import safe_str, safe_repr import twisted.python.log from twisted.python.log import msg as twistedLogMessage from twisted.python.log import addObserver, removeObserver OBSERVER_REMOVED = ( "Temporarily removing observer {observer} due to exception: {e}" ) # # Log level definitions # class InvalidLogLevelError(Exception): """ Someone tried to use a L{LogLevel} that is unknown to the logging system. """ def __init__(self, level): """ @param level: a L{LogLevel} """ super(InvalidLogLevelError, self).__init__(str(level)) self.level = level class LogLevel(Names): """ Constants denoting log levels: - C{debug}: Information of use to a developer of the software, not generally of interest to someone running the software unless they are attempting to diagnose a software issue. - C{info}: Informational events: Routine information about the status of an application, such as incoming connections, startup of a subsystem, etc. - C{warn}: Warnings events: Events that may require greater attention than informational events but are not a systemic failure condition, such as authorization failures, bad data from a network client, etc. - C{error}: Error conditions: Events indicating a systemic failure, such as unhandled exceptions, loss of connectivity to a back-end database, etc. """ debug = NamedConstant() info = NamedConstant() warn = NamedConstant() error = NamedConstant() critical = NamedConstant() @classmethod def levelWithName(cls, name): """ @param name: the name of a L{LogLevel} @return: the L{LogLevel} with the specified C{name} """ try: return cls.lookupByName(name) except ValueError: raise InvalidLogLevelError(name) @classmethod def _priorityForLevel(cls, constant): """ We want log levels to have defined ordering - the order of definition - but they aren't value constants (the only value is the name). This is arguably a bug in Twisted, so this is just a workaround for U{until this is fixed in some way }. """ return cls._levelPriorities[constant] LogLevel._levelPriorities = dict( (constant, idx) for (idx, constant) in (enumerate(LogLevel.iterconstants())) ) # # Mappings to Python's logging module # pythonLogLevelMapping = { LogLevel.debug: logging.DEBUG, LogLevel.info: logging.INFO, LogLevel.warn: logging.WARNING, LogLevel.error: logging.ERROR, LogLevel.critical: logging.CRITICAL, } ## # Loggers ## def formatEvent(event): """ Formats an event as a L{unicode}, using the format in C{event["log_format"]}. This implementation should never raise an exception; if the formatting cannot be done, the returned string will describe the event generically so that a useful message is emitted regardless. @param event: a logging event @return: a L{unicode} """ try: format = event.get("log_format", None) if format is None: raise ValueError("No log format provided") # Make sure format is unicode. if isinstance(format, bytes): # If we get bytes, assume it's UTF-8 bytes format = format.decode("utf-8") elif isinstance(format, unicode): pass else: raise TypeError("Log format must be unicode or bytes, not {0!r}" .format(format)) return formatWithCall(format, event) except BaseException as e: return formatUnformattableEvent(event, e) def formatUnformattableEvent(event, error): """ Formats an event as a L{unicode} that describes the event generically and a formatting error. @param event: a logging event @type dict: L{dict} @param error: the formatting error @type error: L{Exception} @return: a L{unicode} """ try: return ( u"Unable to format event {event!r}: {error}" .format(event=event, error=error) ) except BaseException: # Yikes, something really nasty happened. # # Try to recover as much formattable data as possible; hopefully at # least the namespace is sane, which will help you find the offending # logger. failure = Failure() text = ", ".join(" = ".join((safe_repr(key), safe_repr(value))) for key, value in event.items()) return ( u"MESSAGE LOST: unformattable object logged: {error}\n" u"Recoverable data: {text}\n" u"Exception during formatting:\n{failure}" .format(error=safe_repr(error), failure=failure, text=text) ) class Logger(object): """ Logging object. """ publisher = lambda e: None @staticmethod def _namespaceFromCallingContext(): """ Derive a namespace from the module containing the caller's caller. @return: a namespace """ return inspect.currentframe().f_back.f_back.f_globals["__name__"] def __init__(self, namespace=None, source=None): """ @param namespace: The namespace for this logger. Uses a dotted notation, as used by python modules. If not C{None}, then the name of the module of the caller is used. @param source: The object which is emitting events to this logger; this is automatically set on instances of a class if this L{Logger} is an attribute of that class. """ if namespace is None: namespace = self._namespaceFromCallingContext() self.namespace = namespace self.source = source def __get__(self, oself, type=None): """ When used as a descriptor, i.e.:: # athing.py class Something(object): log = Logger() def hello(self): self.log.info("Hello") a L{Logger}'s namespace will be set to the name of the class it is declared on. In the above example, the namespace would be C{athing.Something}. Additionally, it's source will be set to the actual object referring to the L{Logger}. In the above example, C{Something.log.source} would be C{Something}, and C{Something().log.source} would be an instance of C{Something}. """ if oself is None: source = type else: source = oself return self.__class__( '.'.join([type.__module__, type.__name__]), source ) def __repr__(self): return "<%s %r>" % (self.__class__.__name__, self.namespace) def emit(self, level, format=None, **kwargs): """ Emit a log event to all log observers at the given level. @param level: a L{LogLevel} @param format: a message format using new-style (PEP 3101) formatting. The logging event (which is a L{dict}) is used to render this format string. @param kwargs: additional keyword parameters to include with the event. """ # FIXME: Updated Twisted supports 'in' on constants container if level not in LogLevel.iterconstants(): self.failure( "Got invalid log level {invalidLevel!r} in {logger}.emit().", Failure(InvalidLogLevelError(level)), invalidLevel=level, logger=self, ) # level = LogLevel.error # FIXME: continue to emit? return kwargs.update( log_logger=self, log_level=level, log_namespace=self.namespace, log_source=self.source, log_format=format, log_time=time.time(), ) self.publisher(kwargs) def failure(self, format, failure=None, level=LogLevel.error, **kwargs): """ Log an failure and emit a traceback. For example:: try: frob(knob) except Exception: log.failure("While frobbing {knob}", knob=knob) or:: d = deferredFrob(knob) d.addErrback(lambda f: log.failure, "While frobbing {knob}", f, knob=knob) @param format: a message format using new-style (PEP 3101) formatting. The logging event (which is a L{dict}) is used to render this format string. @param failure: a L{Failure} to log. If C{None}, a L{Failure} is created from the exception in flight. @param level: a L{LogLevel} to use. @param kwargs: additional keyword parameters to include with the event. """ if failure is None: failure = Failure() self.emit(level, format, log_failure=failure, **kwargs) class LegacyLogger(object): """ A logging object that provides some compatibility with the L{twisted.python.log} module. """ def __init__(self, logger=None): if logger is None: self.newStyleLogger = Logger(Logger._namespaceFromCallingContext()) else: self.newStyleLogger = logger def __getattribute__(self, name): try: return super(LegacyLogger, self).__getattribute__(name) except AttributeError: return getattr(twisted.python.log, name) def msg(self, *message, **kwargs): """ This method is API-compatible with L{twisted.python.log.msg} and exists for compatibility with that API. """ if message: message = " ".join(map(safe_str, message)) else: message = None return self.newStyleLogger.emit(LogLevel.info, message, **kwargs) def err(self, _stuff=None, _why=None, **kwargs): """ This method is API-compatible with L{twisted.python.log.err} and exists for compatibility with that API. """ if _stuff is None: _stuff = Failure() elif isinstance(_stuff, Exception): _stuff = Failure(_stuff) if isinstance(_stuff, Failure): self.newStyleLogger.emit(LogLevel.error, failure=_stuff, why=_why, isError=1, **kwargs) else: # We got called with an invalid _stuff. self.newStyleLogger.emit(LogLevel.error, repr(_stuff), why=_why, isError=1, **kwargs) def bindEmit(level): doc = """ Emit a log event at log level L{{{level}}}. @param format: a message format using new-style (PEP 3101) formatting. The logging event (which is a L{{dict}}) is used to render this format string. @param kwargs: additional keyword parameters to include with the event. """.format(level=level.name) # # Attach methods to Logger # def log_emit(self, format=None, **kwargs): self.emit(level, format, **kwargs) log_emit.__doc__ = doc setattr(Logger, level.name, log_emit) def _bindLevels(): for level in LogLevel.iterconstants(): bindEmit(level) _bindLevels() # # Observers # class ILogObserver(Interface): """ An observer which can handle log events. """ def __call__(event): """ Log an event. @type event: C{dict} with (native) C{str} keys. @param event: A dictionary with arbitrary keys as defined by the application emitting logging events, as well as keys added by the logging system, with are: ... """ @implementer(ILogObserver) class LogPublisher(object): """ I{ILogObserver} that fans out events to other observers. Keeps track of a set of L{ILogObserver} objects and forwards events to each. """ log = Logger() def __init__(self, *observers): self._observers = set(observers) @property def observers(self): return frozenset(self._observers) def addObserver(self, observer): """ Registers an observer with this publisher. @param observer: An L{ILogObserver} to add. """ self._observers.add(observer) def removeObserver(self, observer): """ Unregisters an observer with this publisher. @param observer: An L{ILogObserver} to remove. """ try: self._observers.remove(observer) except KeyError: pass def __call__(self, event): for observer in self.observers: try: observer(event) except BaseException as e: # # We have to remove the offending observer because # we're going to badmouth it to all of its friends # (other observers) and it might get offended and # raise again, causing an infinite loop. # self.removeObserver(observer) try: self.log.failure(OBSERVER_REMOVED, observer=observer, e=e) except BaseException: pass finally: self.addObserver(observer) class PredicateResult(Names): """ Predicate results. """ yes = NamedConstant() # Log this no = NamedConstant() # Don't log this maybe = NamedConstant() # No opinion class ILogFilterPredicate(Interface): """ A predicate that determined whether an event should be logged. """ def __call__(event): """ Determine whether an event should be logged. @returns: a L{PredicateResult}. """ @implementer(ILogObserver) class FilteringLogObserver(object): """ L{ILogObserver} that wraps another L{ILogObserver}, but filters out events based on applying a series of L{ILogFilterPredicate}s. """ def __init__(self, observer, predicates): """ @param observer: an L{ILogObserver} to which this observer will forward events. @param predicates: an ordered iterable of predicates to apply to events before forwarding to the wrapped observer. """ self.observer = observer self.predicates = list(predicates) def shouldLogEvent(self, event): """ Determine whether an event should be logged, based C{self.predicates}. @param event: an event """ for predicate in self.predicates: result = predicate(event) if result == PredicateResult.yes: return True if result == PredicateResult.no: return False if result == PredicateResult.maybe: continue raise TypeError("Invalid predicate result: {0!r}".format(result)) return True def __call__(self, event): if self.shouldLogEvent(event): self.observer(event) @implementer(ILogFilterPredicate) class LogLevelFilterPredicate(object): """ L{ILogFilterPredicate} that filters out events with a log level lower than the log level for the event's namespace. Events that not not have a log level or namespace are also dropped. """ def __init__(self): # FIXME: Make this a class variable. But that raises an # _initializeEnumerants constants error in Twisted 12.2.0. self.defaultLogLevel = LogLevel.info self._logLevelsByNamespace = {} self.clearLogLevels() def logLevelForNamespace(self, namespace): """ @param namespace: a logging namespace, or C{None} for the default namespace. @return: the L{LogLevel} for the specified namespace. """ if not namespace: return self._logLevelsByNamespace[None] if namespace in self._logLevelsByNamespace: return self._logLevelsByNamespace[namespace] segments = namespace.split(".") index = len(segments) - 1 while index > 0: namespace = ".".join(segments[:index]) if namespace in self._logLevelsByNamespace: return self._logLevelsByNamespace[namespace] index -= 1 return self._logLevelsByNamespace[None] def setLogLevelForNamespace(self, namespace, level): """ Sets the global log level for a logging namespace. @param namespace: a logging namespace @param level: the L{LogLevel} for the given namespace. """ if level not in LogLevel.iterconstants(): raise InvalidLogLevelError(level) if namespace: self._logLevelsByNamespace[namespace] = level else: self._logLevelsByNamespace[None] = level def clearLogLevels(self): """ Clears all global log levels to the default. """ self._logLevelsByNamespace.clear() self._logLevelsByNamespace[None] = self.defaultLogLevel def __call__(self, event): level = event.get("log_level", None) namespace = event.get("log_namespace", None) if ( level is None or namespace is None or LogLevel._priorityForLevel(level) < LogLevel._priorityForLevel(self.logLevelForNamespace(namespace)) ): return PredicateResult.no return PredicateResult.maybe @implementer(ILogObserver) class LegacyLogObserver(object): """ L{ILogObserver} that wraps an L{ILegacyLogObserver}. """ def __init__(self, legacyObserver): """ @param legacyObserver: an L{ILegacyLogObserver} to which this observer will forward events. """ self.legacyObserver = legacyObserver def __call__(self, event): prefix = "[{log_namespace}#{log_level.name}] ".format(**event) level = event["log_level"] # # Twisted's logging supports indicating a python log level, so let's # provide the equivalent to our logging levels. # if level in pythonLogLevelMapping: event["logLevel"] = pythonLogLevelMapping[level] # Format new style -> old style if event["log_format"]: # # Create an object that implements __str__() in order to # defer the work of formatting until it's needed by a # legacy log observer. # class LegacyFormatStub(object): def __str__(oself): return formatEvent(event).encode("utf-8") event["format"] = prefix + "%(log_legacy)s" event["log_legacy"] = LegacyFormatStub() # log.failure() -> isError blah blah if "log_failure" in event: event["failure"] = event["log_failure"] event["isError"] = 1 event["why"] = "{prefix}{message}".format( prefix=prefix, message=formatEvent(event) ) self.legacyObserver(**event) # FIXME: This could have a better name. class DefaultLogPublisher(object): """ This observer sets up a set of chained observers as follows: 1. B{rootPublisher} - a L{LogPublisher} 2. B{filters}: a L{FilteringLogObserver} that filters out messages using a L{LogLevelFilterPredicate} 3. B{filteredPublisher} - a L{LogPublisher} 4. B{legacyLogObserver} - a L{LegacyLogObserver} wired up to L{twisted.python.log.msg}. This allows any observers registered with Twisted's logging (that is, most observers in presently use) to receive (filtered) events. The purpose of this class is to provide a default log observer with sufficient hooks to enable applications to add observers that can either receive all log messages, or only log messages that are configured to pass though the L{LogLevelFilterPredicate}:: from twext.python.log import Logger, ILogObserver log = Logger() @implementer(ILogObserver) class AMPObserver(object): def __call__(self, event): # eg.: Hold events in a ring buffer and expose them via AMP. ... @implementer(ILogObserver) class FileObserver(object): def __call__(self, event): # eg.: Take events and write them into a file. ... # Send all events to the AMPObserver log.publisher.addObserver(AMPObserver(), filtered=False) # Send filtered events to the FileObserver log.publisher.addObserver(AMPObserver()) With no observers added, the default behavior is that the legacy Twisted logging system sees messages as controlled by L{LogLevelFilterPredicate}. """ def __init__(self): self.legacyLogObserver = LegacyLogObserver(twistedLogMessage) self.filteredPublisher = LogPublisher(self.legacyLogObserver) self.levels = LogLevelFilterPredicate() self.filters = FilteringLogObserver( self.filteredPublisher, (self.levels,) ) self.rootPublisher = LogPublisher(self.filters) def addObserver(self, observer, filtered=True): """ Registers an observer with this publisher. @param observer: An L{ILogObserver} to add. @param filtered: If true, registers C{observer} after filters are applied; otherwise C{observer} will get all events. """ if filtered: self.filteredPublisher.addObserver(observer) self.rootPublisher.removeObserver(observer) else: self.rootPublisher.addObserver(observer) self.filteredPublisher.removeObserver(observer) def removeObserver(self, observer): """ Unregisters an observer with this publisher. @param observer: An L{ILogObserver} to remove. """ self.rootPublisher.removeObserver(observer) self.filteredPublisher.removeObserver(observer) def __call__(self, event): self.rootPublisher(event) Logger.publisher = DefaultLogPublisher() # # Utilities # class CallMapping(object): def __init__(self, submapping): self._submapping = submapping def __getitem__(self, key): callit = key.endswith(u"()") realKey = key[:-2] if callit else key value = self._submapping[realKey] if callit: value = value() return value def formatWithCall(formatString, mapping): """ Format a string like L{unicode.format}, but: - taking only a name mapping; no positional arguments - with the additional syntax that an empty set of parentheses correspond to a formatting item that should be called, and its result C{str}'d, rather than calling C{str} on the element directly as normal. For example:: >>> formatWithCall("{string}, {function()}.", ... dict(string="just a string", ... function=lambda: "a function")) 'just a string, a function.' @param formatString: A PEP-3101 format string. @type formatString: L{unicode} @param mapping: A L{dict}-like object to format. @return: The string with formatted values interpolated. @rtype: L{unicode} """ return unicode( theFormatter.vformat(formatString, (), CallMapping(mapping)) ) theFormatter = Formatter() def replaceTwistedLoggers(): """ Visit all Python modules that have been loaded and: - replace L{twisted.python.log} with a L{LegacyLogger} - replace L{twisted.python.log.msg} with a L{LegacyLogger}'s C{msg} - replace L{twisted.python.log.err} with a L{LegacyLogger}'s C{err} """ log = Logger() for moduleName, module in sys.modules.iteritems(): # Oddly, this happens if module is None: continue # Don't patch Twisted's logging module if module in (twisted.python, twisted.python.log): continue # Don't patch this module if moduleName is __name__: continue try: for name, obj in module.__dict__.iteritems(): try: newLogger = Logger(namespace=module.__name__) except AttributeError: # Can't look up __name__. A hack in the "six" module causes # this. Skip the module. # See https://trac.calendarserver.org/ticket/832 continue legacyLogger = LegacyLogger(logger=newLogger) if obj is twisted.python.log: log.info( "Replacing Twisted log module object {0} in {1}" .format(name, module.__name__) ) setattr(module, name, legacyLogger) elif obj is twisted.python.log.msg: log.info( "Replacing Twisted log.msg object {0} in {1}" .format(name, module.__name__) ) setattr(module, name, legacyLogger.msg) elif obj is twisted.python.log.err: log.info( "Replacing Twisted log.err object {0} in {1}" .format(name, module.__name__) ) setattr(module, name, legacyLogger.err) except RuntimeError as e: # Python could use more specific exceptions, eh. # What we mean to catch is: # RuntimeError: dictionary changed size during iteration log.error( "Unable to replace twisted loggers for module {module}: " "{error}", module=module, error=e ) # FIXME: This may not be needed; look into removing it. class StandardIOObserver(object): """ (Legacy) log observer that writes to standard I/O. """ def emit(self, eventDict): text = None if eventDict["isError"]: output = stderr if "failure" in eventDict: text = eventDict["failure"].getTraceback() else: output = stdout if not text: text = formatEvent(eventDict) + "\n" output.write(text) output.flush() def start(self): addObserver(self.emit) def stop(self): removeObserver(self.emit)