[CalendarServer-changes] [11336] CalendarServer/trunk/twext/python
source_changes at macosforge.org
source_changes at macosforge.org
Thu Jun 13 11:41:59 PDT 2013
Revision: 11336
http://trac.calendarserver.org//changeset/11336
Author: wsanchez at apple.com
Date: 2013-06-13 11:41:59 -0700 (Thu, 13 Jun 2013)
Log Message:
-----------
Add a LogPublisher class and a default log publisher.
Remove legacy event glue from Logger.emit() and move that logic to a new LegacyLogObserverWrapper.
Modified Paths:
--------------
CalendarServer/trunk/twext/python/log.py
CalendarServer/trunk/twext/python/test/test_log.py
Modified: CalendarServer/trunk/twext/python/log.py
===================================================================
--- CalendarServer/trunk/twext/python/log.py 2013-06-12 20:56:26 UTC (rev 11335)
+++ CalendarServer/trunk/twext/python/log.py 2013-06-13 18:41:59 UTC (rev 11336)
@@ -50,7 +50,12 @@
#
# TODO List:
#
-# * Filter in observers, not emit()
+# * Filter in observers, not emit() - use a wrapper observer
+# * Expose the default log observer (TheLogPublisher)
+# * Specifically, expose addObserver and removeObserver so one can register other observers
+# * Check the unicode situation for sanity
+# * Change the default log observer to something non-legacy
+# * Register a legacy observer with Twisted's logging that forwards to this module
#
__all__ = [
@@ -63,20 +68,24 @@
"LegacyLogger",
"ILogObserver",
"ILegacyLogObserver",
- "StandardIOObserver",
+ "LogPublisher",
+ "LegacyLogObserverWrapper",
+ #"StandardIOObserver",
]
from sys import stdout, stderr
import inspect
import logging
+import time
-from zope.interface import Interface
+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
from twisted.python.log import msg as twistedLogMessage
from twisted.python.log import addObserver, removeObserver
+from twisted.python.log import ILogObserver as ILegacyLogObserver
@@ -205,9 +214,9 @@
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 messages to this logger;
- this is automatically set on instances of a class if this L{Logger}
- is an attribute of that class.
+ @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:
currentFrame = inspect.currentframe()
@@ -248,71 +257,97 @@
return "<%s %r>" % (self.__class__.__name__, self.namespace)
+ @classmethod
+ def formatEvent(cls, 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 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 type(format) is bytes:
+ # If we get bytes, assume it's UTF-8 bytes
+ format = format.decode("utf-8")
+ else:
+ # For anything else, assume we can just convert to unicode
+ format = unicode(format)
+
+ return format.format(**event)
+
+ except Exception as e:
+ return cls.formatUnformattableEvent(event, e)
+
+
+ @classmethod
+ def formatUnformattableEvent(cls, event, error):
+ """
+ Formats an event as a L{unicode} that describes the event
+ generically and a formatting error.
+
+ @param event: a logging event
+
+ @param error: the formatting error
+
+ @return: a L{unicode}
+ """
+ return (
+ u"Unable to format event {event}: {error}"
+ .format(event=event, error=error)
+ )
+
+
def emit(self, level, format=None, **kwargs):
"""
- Emit a log message to all log observers at the given level.
+ Emit a log event to all log observers at the given level.
@param level: a L{LogLevel}
- @param format: a message format using PEP3101 formatting. All
- variables in C{kwargs} are available.
+ @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
- message.
+ @param kwargs: additional keyword parameters to include with
+ the event.
"""
if level not in LogLevel.iterconstants(): # FIXME: Updated Twisted supports 'in' on constants container
self.failure(
- "Got invalid log level in {logger}.emit().",
+ "Got invalid log {invalidLevel} level in {logger}.emit().",
Failure(InvalidLogLevelError(level)),
+ invalidLevel = level,
logger = self,
)
- level = LogLevel.error
+ #level = LogLevel.error
return
# FIXME: Filtering should be done by the log observer(s)
if not self.willLogAtLevel(level):
return
- kwargs.update(
+ event = kwargs
+ event.update(
+ log_logger = self,
log_level = level,
- log_levelName = level.name, # FIXME: Remove
log_namespace = self.namespace,
log_source = self.source,
+ log_format = format,
+ log_time = time.time(),
)
- #
- # Twisted's logging supports indicating a python log level, so let's
- # use the equivalent to our logging level.
- #
- if level in pythonLogLevelMapping:
- kwargs["logLevel"] = pythonLogLevelMapping[level]
+ TheLogPublisher(event)
- prefix = "[%(log_namespace)s#%(log_levelName)s] "
- if "log_failure" in kwargs:
- # FIXME: legacy cruft: failure, isError, why
- kwargs["failure"] = kwargs["log_failure"]
- kwargs["isError"] = 1
- kwargs["why"] = "%s%s" % (prefix % kwargs, format % kwargs)
-
- if 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__(self):
- return format.format(**kwargs)
-
- # FIXME: legacy cruft: format
- # FIXME: Adding the prefix should be the observer's problem
- kwargs["log_format"] = kwargs["format"] = prefix + "%(log_legacy)s"
- kwargs["log_legacy"] = LegacyFormatStub()
-
- twistedLogMessage(**kwargs)
-
-
def failure(self, format, failure=None, **kwargs):
"""
Log an failure and emit a traceback.
@@ -321,7 +356,7 @@
try:
frob(knob)
- except:
+ except Exception:
log.failure("While frobbing {knob}", knob=knob)
or::
@@ -329,13 +364,15 @@
d = deferred_frob(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 message: a message
-
@param kwargs: additional keyword parameters to include with the
- message.
+ event.
"""
if failure is None:
failure=Failure()
@@ -399,9 +436,6 @@
elif isinstance(_stuff, Exception):
_stuff = Failure(_stuff)
- # FIXME: We are setting isError=0 below to work around
- # existing bugs, should be =1.
-
if isinstance(_stuff, Failure):
self.emit(LogLevel.error, failure=_stuff, why=_why, isError=1, **kwargs)
else:
@@ -412,12 +446,15 @@
def bindEmit(level):
doc = """
- Emit a log message at log level L{%s}.
+ Emit a log event at log level L{{{level}}}.
- @param message: a message
+ @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 message.
- """ % (level.__class__.__name__,)
+ @param kwargs: additional keyword parameters to include with the
+ event.
+ """.format(level=level.name)
#
# Attach methods to Logger
@@ -448,35 +485,144 @@
"""
An observer which can handle log events.
"""
- def __call__(eventDict):
+ def __call__(event):
"""
Log an event.
- @type eventDict: C{dict} with C{str} keys.
+ @type event: C{dict} with C{str} keys.
- @param eventDict: A dictionary with arbitrary keys as defined
- by the application emitting logging events, as well as
- keys added by the logging system, with are:
+ @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:
...
"""
-# Import the legacy interface from Twisted
-from twisted.python.log import ILogObserver as ILegacyLogObserver
+ at implementer(ILogObserver)
+class LogPublisher(object):
+ """
+ Log publisher that fans out events to other observers.
-class FilteringLogObserverWrapper(object):
+ Keeps track of a set of L{ILogObserver} objects and forwards
+ events to each.
"""
+ log = Logger()
+
+ def __init__(self):
+ self._observers = set()
+
+
+ @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.
+ """
+ self._observers.remove(observer)
+
+
+ def __call__(self, event):
+ for observer in self.observers:
+ try:
+ observer(event)
+ except KeyboardInterrupt:
+ raise
+ except Exception:
+ #
+ # 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 {observer} raised an exception; removing.")
+ Failure().printTraceback()
+ except Exception:
+ pass
+ finally:
+ self.addObserver(observer)
+
+
+
+ at implementer(ILogObserver)
+class LegacyLogObserverWrapper(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__(self):
+ return self.formatEvent(event)
+
+ # FIXME: Adding the prefix should be the observer's problem
+ event["format"] = prefix + "%(log_legacy)s"
+ event["log_legacy"] = LegacyFormatStub()
+
+ # log.failure() -> isError blah blah
+ if "log_failure" in event:
+ formatEvent = event.get("log_logger", Logger).formatEvent
+
+ event["failure"] = event["log_failure"]
+ event["isError"] = 1
+ event["why"] = "{prefix}{message}".format(prefix=prefix, message=formatEvent(event))
+
+ self.legacyObserver(**event)
+
+
+
+TheLogPublisher = LogPublisher()
+TheLogPublisher.addObserver(LegacyLogObserverWrapper(twistedLogMessage))
+
+
+
+######################################################################
# FIXME: This may not be needed; look into removing it.
class StandardIOObserver(object):
"""
- Log observer that writes to standard I/O.
+ (Legacy) log observer that writes to standard I/O.
"""
def emit(self, eventDict):
text = None
Modified: CalendarServer/trunk/twext/python/test/test_log.py
===================================================================
--- CalendarServer/trunk/twext/python/test/test_log.py 2013-06-12 20:56:26 UTC (rev 11335)
+++ CalendarServer/trunk/twext/python/test/test_log.py 2013-06-13 18:41:59 UTC (rev 11336)
@@ -33,15 +33,23 @@
class TestLoggerMixIn(object):
def emit(self, level, format=None, **kwargs):
- def observer(eventDict):
- self.eventDict = eventDict
+ if False:
+ print "*"*60
+ print "level =", level
+ print "format =", format
+ for key, value in kwargs.items():
+ print key, "=", value
+ print "*"*60
+ def observer(event):
+ self.event = event
+
twistedLogging.addObserver(observer)
+ try:
+ Logger.emit(self, level, format, **kwargs)
+ finally:
+ twistedLogging.removeObserver(observer)
- Logger.emit(self, level, format, **kwargs)
-
- twistedLogging.removeObserver(observer)
-
self.emitted = {
"level" : level,
"format": format,
@@ -126,7 +134,11 @@
obj = LogComposedObject("hello")
log = obj.log
log.error("Hello, {log_source}.")
- stuff = twistedLogging.textFromEventDict(log.eventDict)
+
+ self.assertIn("log_source", log.event)
+ self.assertEquals(log.event["log_source"], obj)
+
+ stuff = log.formatEvent(log.event)
self.assertIn("Hello, <LogComposedObject hello>.", stuff)
@@ -152,23 +164,22 @@
self.assertEquals(log.emitted["kwargs"]["junk"], message)
if log.willLogAtLevel(level):
- #self.assertEquals(log.eventDict["log_format"], format) # FIXME: doesn't work due to emit() mangling the format
- self.assertEquals(log.eventDict["log_level"], level)
- self.assertEquals(log.eventDict["log_levelName"], level.name)
- self.assertEquals(log.eventDict["log_namespace"], __name__)
- self.assertEquals(log.eventDict["log_source"], None)
+ self.assertEquals(log.event["log_format"], format)
+ self.assertEquals(log.event["log_level"], level)
+ self.assertEquals(log.event["log_namespace"], __name__)
+ self.assertEquals(log.event["log_source"], None)
- self.assertEquals(log.eventDict["logLevel"], pythonLogLevelMapping[level])
+ self.assertEquals(log.event["logLevel"], pythonLogLevelMapping[level])
- self.assertEquals(log.eventDict["junk"], message)
+ self.assertEquals(log.event["junk"], message)
# FIXME: this checks the end of message because we do formatting in emit()
self.assertEquals(
- twistedLogging.textFromEventDict(log.eventDict)[-len(message):],
+ log.formatEvent(log.event),
message
)
else:
- self.assertFalse(hasattr(log, "eventDict"))
+ self.assertFalse(hasattr(log, "event"))
def test_defaultFailure(self):
@@ -203,19 +214,16 @@
"*",
log_format = "#",
log_level = LogLevel.error,
- log_levelName = "*level name*",
log_namespace = "*namespace*",
log_source = "*source*",
)
# FIXME: Should conflicts log errors?
- self.assertNotEquals(log.eventDict["log_format"], "*")
- self.assertNotEquals(log.eventDict["log_format"], "#")
- self.assertEquals(log.eventDict["log_level"], LogLevel.warn)
- self.assertEquals(log.eventDict["log_levelName"], LogLevel.warn.name)
- self.assertEquals(log.eventDict["log_namespace"], log.namespace)
- self.assertEquals(log.eventDict["log_source"], None)
+ self.assertEquals(log.event["log_format"], "*")
+ self.assertEquals(log.event["log_level"], LogLevel.warn)
+ self.assertEquals(log.event["log_namespace"], log.namespace)
+ self.assertEquals(log.event["log_source"], None)
def test_defaultLogLevel(self):
@@ -342,6 +350,22 @@
self.assertEquals(len(errors), 1)
+ def test_formatEvent(self):
+ """
+ Test formatting.
+ """
+ def formatEvent(log_format, **event):
+ event["log_format"] = log_format
+ result = Logger.formatEvent(event)
+ self.assertIdentical(type(result), unicode) # Always returns unicode
+ return result
+
+ self.assertEquals("", formatEvent(""))
+ self.assertEquals("abc", formatEvent("{x}", x="abc"))
+ self.assertEquals(u'S\xe1nchez', formatEvent("S\xc3\xa1nchez")) # bytes->unicode
+ self.assertIn("Unable to format event", formatEvent("S\xe1nchez")) # Non-UTF-8 bytes
+
+
def test_legacy_msg(self):
"""
Test LegacyLogger's log.msg()
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.macosforge.org/pipermail/calendarserver-changes/attachments/20130613/790dac26/attachment-0001.html>
More information about the calendarserver-changes
mailing list