<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.1//EN"
"http://www.w3.org/TR/xhtml11/DTD/xhtml11.dtd">
<html xmlns="http://www.w3.org/1999/xhtml">
<head><meta http-equiv="content-type" content="text/html; charset=utf-8" />
<title>[11336] CalendarServer/trunk/twext/python</title>
</head>
<body>

<style type="text/css"><!--
#msg dl.meta { border: 1px #006 solid; background: #369; padding: 6px; color: #fff; }
#msg dl.meta dt { float: left; width: 6em; font-weight: bold; }
#msg dt:after { content:':';}
#msg dl, #msg dt, #msg ul, #msg li, #header, #footer, #logmsg { font-family: verdana,arial,helvetica,sans-serif; font-size: 10pt;  }
#msg dl a { font-weight: bold}
#msg dl a:link    { color:#fc3; }
#msg dl a:active  { color:#ff0; }
#msg dl a:visited { color:#cc6; }
h3 { font-family: verdana,arial,helvetica,sans-serif; font-size: 10pt; font-weight: bold; }
#msg pre { overflow: auto; background: #ffc; border: 1px #fa0 solid; padding: 6px; }
#logmsg { background: #ffc; border: 1px #fa0 solid; padding: 1em 1em 0 1em; }
#logmsg p, #logmsg pre, #logmsg blockquote { margin: 0 0 1em 0; }
#logmsg p, #logmsg li, #logmsg dt, #logmsg dd { line-height: 14pt; }
#logmsg h1, #logmsg h2, #logmsg h3, #logmsg h4, #logmsg h5, #logmsg h6 { margin: .5em 0; }
#logmsg h1:first-child, #logmsg h2:first-child, #logmsg h3:first-child, #logmsg h4:first-child, #logmsg h5:first-child, #logmsg h6:first-child { margin-top: 0; }
#logmsg ul, #logmsg ol { padding: 0; list-style-position: inside; margin: 0 0 0 1em; }
#logmsg ul { text-indent: -1em; padding-left: 1em; }#logmsg ol { text-indent: -1.5em; padding-left: 1.5em; }
#logmsg > ul, #logmsg > ol { margin: 0 0 1em 0; }
#logmsg pre { background: #eee; padding: 1em; }
#logmsg blockquote { border: 1px solid #fa0; border-left-width: 10px; padding: 1em 1em 0 1em; background: white;}
#logmsg dl { margin: 0; }
#logmsg dt { font-weight: bold; }
#logmsg dd { margin: 0; padding: 0 0 0.5em 0; }
#logmsg dd:before { content:'\00bb';}
#logmsg table { border-spacing: 0px; border-collapse: collapse; border-top: 4px solid #fa0; border-bottom: 1px solid #fa0; background: #fff; }
#logmsg table th { text-align: left; font-weight: normal; padding: 0.2em 0.5em; border-top: 1px dotted #fa0; }
#logmsg table td { text-align: right; border-top: 1px dotted #fa0; padding: 0.2em 0.5em; }
#logmsg table thead th { text-align: center; border-bottom: 1px solid #fa0; }
#logmsg table th.Corner { text-align: left; }
#logmsg hr { border: none 0; border-top: 2px dashed #fa0; height: 1px; }
#header, #footer { color: #fff; background: #636; border: 1px #300 solid; padding: 6px; }
#patch { width: 100%; }
#patch h4 {font-family: verdana,arial,helvetica,sans-serif;font-size:10pt;padding:8px;background:#369;color:#fff;margin:0;}
#patch .propset h4, #patch .binary h4 {margin:0;}
#patch pre {padding:0;line-height:1.2em;margin:0;}
#patch .diff {width:100%;background:#eee;padding: 0 0 10px 0;overflow:auto;}
#patch .propset .diff, #patch .binary .diff  {padding:10px 0;}
#patch span {display:block;padding:0 10px;}
#patch .modfile, #patch .addfile, #patch .delfile, #patch .propset, #patch .binary, #patch .copfile {border:1px solid #ccc;margin:10px 0;}
#patch ins {background:#dfd;text-decoration:none;display:block;padding:0 10px;}
#patch del {background:#fdd;text-decoration:none;display:block;padding:0 10px;}
#patch .lines, .info {color:#888;background:#fff;}
--></style>
<div id="msg">
<dl class="meta">
<dt>Revision</dt> <dd><a href="http://trac.calendarserver.org//changeset/11336">11336</a></dd>
<dt>Author</dt> <dd>wsanchez@apple.com</dd>
<dt>Date</dt> <dd>2013-06-13 11:41:59 -0700 (Thu, 13 Jun 2013)</dd>
</dl>

<h3>Log Message</h3>
<pre>Add a LogPublisher class and a default log publisher.
Remove legacy event glue from Logger.emit() and move that logic to a new LegacyLogObserverWrapper.</pre>

<h3>Modified Paths</h3>
<ul>
<li><a href="#CalendarServertrunktwextpythonlogpy">CalendarServer/trunk/twext/python/log.py</a></li>
<li><a href="#CalendarServertrunktwextpythontesttest_logpy">CalendarServer/trunk/twext/python/test/test_log.py</a></li>
</ul>

</div>
<div id="patch">
<h3>Diff</h3>
<a id="CalendarServertrunktwextpythonlogpy"></a>
<div class="modfile"><h4>Modified: CalendarServer/trunk/twext/python/log.py (11335 => 11336)</h4>
<pre class="diff"><span>
<span class="info">--- 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)
</span><span class="lines">@@ -50,7 +50,12 @@
</span><span class="cx"> #
</span><span class="cx"> # TODO List:
</span><span class="cx"> #
</span><del>-# * Filter in observers, not emit()
</del><ins>+# * 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
</ins><span class="cx"> #
</span><span class="cx"> 
</span><span class="cx"> __all__ = [
</span><span class="lines">@@ -63,20 +68,24 @@
</span><span class="cx">     &quot;LegacyLogger&quot;,
</span><span class="cx">     &quot;ILogObserver&quot;,
</span><span class="cx">     &quot;ILegacyLogObserver&quot;,
</span><del>-    &quot;StandardIOObserver&quot;,
</del><ins>+    &quot;LogPublisher&quot;,
+    &quot;LegacyLogObserverWrapper&quot;,
+    #&quot;StandardIOObserver&quot;,
</ins><span class="cx"> ]
</span><span class="cx"> 
</span><span class="cx"> from sys import stdout, stderr
</span><span class="cx"> 
</span><span class="cx"> import inspect
</span><span class="cx"> import logging
</span><ins>+import time
</ins><span class="cx"> 
</span><del>-from zope.interface import Interface
</del><ins>+from zope.interface import Interface, implementer
</ins><span class="cx"> from twisted.python.constants import NamedConstant, Names
</span><span class="cx"> from twisted.python.failure import Failure
</span><span class="cx"> from twisted.python.reflect import safe_str
</span><span class="cx"> from twisted.python.log import msg as twistedLogMessage
</span><span class="cx"> from twisted.python.log import addObserver, removeObserver
</span><ins>+from twisted.python.log import ILogObserver as ILegacyLogObserver
</ins><span class="cx"> 
</span><span class="cx"> 
</span><span class="cx"> 
</span><span class="lines">@@ -205,9 +214,9 @@
</span><span class="cx">             notation, as used by python modules.  If not C{None}, then the name
</span><span class="cx">             of the module of the caller is used.
</span><span class="cx"> 
</span><del>-        @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.
</del><ins>+        @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.
</ins><span class="cx">         &quot;&quot;&quot;
</span><span class="cx">         if namespace is None:
</span><span class="cx">             currentFrame = inspect.currentframe()
</span><span class="lines">@@ -248,71 +257,97 @@
</span><span class="cx">         return &quot;&lt;%s %r&gt;&quot; % (self.__class__.__name__, self.namespace)
</span><span class="cx"> 
</span><span class="cx"> 
</span><ins>+    @classmethod
+    def formatEvent(cls, event):
+        &quot;&quot;&quot;
+        Formats an event as a L{unicode}, using the format in
+        C{event[&quot;log_format&quot;]}.  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}
+        &quot;&quot;&quot;
+        try:
+            format = event.get(&quot;log_format&quot;, None)
+
+            if format is None:
+                raise ValueError(&quot;No log format provided&quot;)
+
+            # Make sure format is unicode.
+            if type(format) is bytes:
+                # If we get bytes, assume it's UTF-8 bytes
+                format = format.decode(&quot;utf-8&quot;)
+            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):
+        &quot;&quot;&quot;
+        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}
+        &quot;&quot;&quot;
+        return (
+            u&quot;Unable to format event {event}: {error}&quot;
+            .format(event=event, error=error)
+        )
+
+
</ins><span class="cx">     def emit(self, level, format=None, **kwargs):
</span><span class="cx">         &quot;&quot;&quot;
</span><del>-        Emit a log message to all log observers at the given level.
</del><ins>+        Emit a log event to all log observers at the given level.
</ins><span class="cx"> 
</span><span class="cx">         @param level: a L{LogLevel}
</span><span class="cx"> 
</span><del>-        @param format: a message format using PEP3101 formatting.  All
-            variables in C{kwargs} are available.
</del><ins>+        @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.
</ins><span class="cx"> 
</span><del>-        @param kwargs: additional keyword parameters to include with the
-            message.
</del><ins>+        @param kwargs: additional keyword parameters to include with
+            the event.
</ins><span class="cx">         &quot;&quot;&quot;
</span><span class="cx">         if level not in LogLevel.iterconstants(): # FIXME: Updated Twisted supports 'in' on constants container
</span><span class="cx">             self.failure(
</span><del>-                &quot;Got invalid log level in {logger}.emit().&quot;,
</del><ins>+                &quot;Got invalid log {invalidLevel} level in {logger}.emit().&quot;,
</ins><span class="cx">                 Failure(InvalidLogLevelError(level)),
</span><ins>+                invalidLevel = level,
</ins><span class="cx">                 logger = self,
</span><span class="cx">             )
</span><del>-            level = LogLevel.error
</del><ins>+            #level = LogLevel.error
</ins><span class="cx">             return
</span><span class="cx"> 
</span><span class="cx">         # FIXME: Filtering should be done by the log observer(s)
</span><span class="cx">         if not self.willLogAtLevel(level):
</span><span class="cx">             return
</span><span class="cx"> 
</span><del>-        kwargs.update(
</del><ins>+        event = kwargs
+        event.update(
+            log_logger    = self,
</ins><span class="cx">             log_level     = level,
</span><del>-            log_levelName = level.name, # FIXME: Remove
</del><span class="cx">             log_namespace = self.namespace,
</span><span class="cx">             log_source    = self.source,
</span><ins>+            log_format    = format,
+            log_time      = time.time(),
</ins><span class="cx">         )
</span><span class="cx"> 
</span><del>-        #
-        # Twisted's logging supports indicating a python log level, so let's
-        # use the equivalent to our logging level.
-        #
-        if level in pythonLogLevelMapping:
-            kwargs[&quot;logLevel&quot;] = pythonLogLevelMapping[level]
</del><ins>+        TheLogPublisher(event)
</ins><span class="cx"> 
</span><del>-        prefix = &quot;[%(log_namespace)s#%(log_levelName)s] &quot;
</del><span class="cx"> 
</span><del>-        if &quot;log_failure&quot; in kwargs:
-            # FIXME: legacy cruft: failure, isError, why
-            kwargs[&quot;failure&quot;] = kwargs[&quot;log_failure&quot;]
-            kwargs[&quot;isError&quot;] = 1
-            kwargs[&quot;why&quot;] = &quot;%s%s&quot; % (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[&quot;log_format&quot;] = kwargs[&quot;format&quot;] = prefix + &quot;%(log_legacy)s&quot;
-            kwargs[&quot;log_legacy&quot;] = LegacyFormatStub()
-
-        twistedLogMessage(**kwargs)
-
-
</del><span class="cx">     def failure(self, format, failure=None, **kwargs):
</span><span class="cx">         &quot;&quot;&quot;
</span><span class="cx">         Log an failure and emit a traceback.
</span><span class="lines">@@ -321,7 +356,7 @@
</span><span class="cx"> 
</span><span class="cx">             try:
</span><span class="cx">                 frob(knob)
</span><del>-            except:
</del><ins>+            except Exception:
</ins><span class="cx">                 log.failure(&quot;While frobbing {knob}&quot;, knob=knob)
</span><span class="cx"> 
</span><span class="cx">         or::
</span><span class="lines">@@ -329,13 +364,15 @@
</span><span class="cx">             d = deferred_frob(knob)
</span><span class="cx">             d.addErrback(lambda f: log.failure, &quot;While frobbing {knob}&quot;, f, knob=knob)
</span><span class="cx"> 
</span><ins>+        @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.
+
</ins><span class="cx">         @param failure: a L{Failure} to log.  If C{None}, a L{Failure} is
</span><span class="cx">             created from the exception in flight.
</span><span class="cx"> 
</span><del>-        @param message: a message
-
</del><span class="cx">         @param kwargs: additional keyword parameters to include with the
</span><del>-            message.
</del><ins>+            event.
</ins><span class="cx">         &quot;&quot;&quot;
</span><span class="cx">         if failure is None:
</span><span class="cx">             failure=Failure()
</span><span class="lines">@@ -399,9 +436,6 @@
</span><span class="cx">         elif isinstance(_stuff, Exception):
</span><span class="cx">             _stuff = Failure(_stuff)
</span><span class="cx"> 
</span><del>-        # FIXME: We are setting isError=0 below to work around
-        # existing bugs, should be =1.
-
</del><span class="cx">         if isinstance(_stuff, Failure):
</span><span class="cx">             self.emit(LogLevel.error, failure=_stuff, why=_why, isError=1, **kwargs)
</span><span class="cx">         else:
</span><span class="lines">@@ -412,12 +446,15 @@
</span><span class="cx"> 
</span><span class="cx"> def bindEmit(level):
</span><span class="cx">     doc = &quot;&quot;&quot;
</span><del>-    Emit a log message at log level L{%s}.
</del><ins>+    Emit a log event at log level L{{{level}}}.
</ins><span class="cx"> 
</span><del>-    @param message: a message
</del><ins>+    @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.
</ins><span class="cx"> 
</span><del>-    @param kwargs: additional keyword parameters to include with the message.
-    &quot;&quot;&quot; % (level.__class__.__name__,)
</del><ins>+    @param kwargs: additional keyword parameters to include with the
+        event.
+    &quot;&quot;&quot;.format(level=level.name)
</ins><span class="cx"> 
</span><span class="cx">     #
</span><span class="cx">     # Attach methods to Logger
</span><span class="lines">@@ -448,35 +485,144 @@
</span><span class="cx">     &quot;&quot;&quot;
</span><span class="cx">     An observer which can handle log events.
</span><span class="cx">     &quot;&quot;&quot;
</span><del>-    def __call__(eventDict):
</del><ins>+    def __call__(event):
</ins><span class="cx">         &quot;&quot;&quot;
</span><span class="cx">         Log an event.
</span><span class="cx"> 
</span><del>-        @type eventDict: C{dict} with C{str} keys.
</del><ins>+        @type event: C{dict} with C{str} keys.
</ins><span class="cx"> 
</span><del>-        @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:
</del><ins>+        @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:
</ins><span class="cx">             ...
</span><span class="cx">         &quot;&quot;&quot;
</span><span class="cx"> 
</span><span class="cx"> 
</span><del>-# Import the legacy interface from Twisted
-from twisted.python.log import ILogObserver as ILegacyLogObserver
</del><span class="cx"> 
</span><ins>+@implementer(ILogObserver)
+class LogPublisher(object):
+    &quot;&quot;&quot;
+    Log publisher that fans out events to other observers.
</ins><span class="cx"> 
</span><del>-class FilteringLogObserverWrapper(object):
</del><ins>+    Keeps track of a set of L{ILogObserver} objects and forwards
+    events to each.
</ins><span class="cx">     &quot;&quot;&quot;
</span><ins>+    log = Logger()
+
+    def __init__(self):
+        self._observers = set()
+
+
+    @property
+    def observers(self):
+        return frozenset(self._observers)
+
+
+    def addObserver(self, observer):
+        &quot;&quot;&quot;
+        Registers an observer with this publisher.
+
+        @param observer: An L{ILogObserver} to add.
+        &quot;&quot;&quot;
+        self._observers.add(observer)
+
+
+    def removeObserver(self, observer):
+        &quot;&quot;&quot;
+        Unregisters an observer with this publisher.
+
+        @param observer: An L{ILogObserver} to remove.
+        &quot;&quot;&quot;
+        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(&quot;Observer {observer} raised an exception; removing.&quot;)
+                    Failure().printTraceback()
+                except Exception:
+                    pass
+                finally:
+                    self.addObserver(observer)
+
+
+
+@implementer(ILogObserver)
+class LegacyLogObserverWrapper(object):
</ins><span class="cx">     &quot;&quot;&quot;
</span><ins>+    L{ILogObserver} that wraps an L{ILegacyLogObserver}.
+    &quot;&quot;&quot;
+    def __init__(self, legacyObserver):
+        &quot;&quot;&quot;
+        @param legacyObserver: an L{ILegacyLogObserver} to which this
+            observer will forward events.
+        &quot;&quot;&quot;
+        self.legacyObserver = legacyObserver
</ins><span class="cx"> 
</span><ins>+    
+    def __call__(self, event): 
+        prefix = &quot;[{log_namespace}#{log_level.name}] &quot;.format(**event)
</ins><span class="cx"> 
</span><ins>+        level = event[&quot;log_level&quot;]
</ins><span class="cx"> 
</span><ins>+        #
+        # Twisted's logging supports indicating a python log level, so let's
+        # provide the equivalent to our logging levels.
+        #
+        if level in pythonLogLevelMapping:
+            event[&quot;logLevel&quot;] = pythonLogLevelMapping[level]
</ins><span class="cx"> 
</span><ins>+        # Format new style -&gt; old style
+        if event[&quot;log_format&quot;]:
+            #
+            # 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[&quot;format&quot;] = prefix + &quot;%(log_legacy)s&quot;
+            event[&quot;log_legacy&quot;] = LegacyFormatStub()
+
+        # log.failure() -&gt; isError blah blah
+        if &quot;log_failure&quot; in event:
+            formatEvent = event.get(&quot;log_logger&quot;, Logger).formatEvent
+
+            event[&quot;failure&quot;] = event[&quot;log_failure&quot;]
+            event[&quot;isError&quot;] = 1
+            event[&quot;why&quot;] = &quot;{prefix}{message}&quot;.format(prefix=prefix, message=formatEvent(event))
+
+        self.legacyObserver(**event)
+
+
+
+TheLogPublisher = LogPublisher()
+TheLogPublisher.addObserver(LegacyLogObserverWrapper(twistedLogMessage))
+
+
+
+######################################################################
</ins><span class="cx"> # FIXME: This may not be needed; look into removing it.
</span><span class="cx"> 
</span><span class="cx"> class StandardIOObserver(object):
</span><span class="cx">     &quot;&quot;&quot;
</span><del>-    Log observer that writes to standard I/O.
</del><ins>+    (Legacy) log observer that writes to standard I/O.
</ins><span class="cx">     &quot;&quot;&quot;
</span><span class="cx">     def emit(self, eventDict):
</span><span class="cx">         text = None
</span></span></pre></div>
<a id="CalendarServertrunktwextpythontesttest_logpy"></a>
<div class="modfile"><h4>Modified: CalendarServer/trunk/twext/python/test/test_log.py (11335 => 11336)</h4>
<pre class="diff"><span>
<span class="info">--- 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)
</span><span class="lines">@@ -33,15 +33,23 @@
</span><span class="cx"> 
</span><span class="cx"> class TestLoggerMixIn(object):
</span><span class="cx">     def emit(self, level, format=None, **kwargs):
</span><del>-        def observer(eventDict):
-            self.eventDict = eventDict
</del><ins>+        if False:
+            print &quot;*&quot;*60
+            print &quot;level =&quot;, level
+            print &quot;format =&quot;, format
+            for key, value in kwargs.items():
+                print key, &quot;=&quot;, value
+            print &quot;*&quot;*60
</ins><span class="cx"> 
</span><ins>+        def observer(event):
+            self.event = event
+
</ins><span class="cx">         twistedLogging.addObserver(observer)
</span><ins>+        try:
+            Logger.emit(self, level, format, **kwargs)
+        finally:
+            twistedLogging.removeObserver(observer)
</ins><span class="cx"> 
</span><del>-        Logger.emit(self, level, format, **kwargs)
-
-        twistedLogging.removeObserver(observer)
-
</del><span class="cx">         self.emitted = {
</span><span class="cx">             &quot;level&quot; : level,
</span><span class="cx">             &quot;format&quot;: format,
</span><span class="lines">@@ -126,7 +134,11 @@
</span><span class="cx">         obj = LogComposedObject(&quot;hello&quot;)
</span><span class="cx">         log = obj.log
</span><span class="cx">         log.error(&quot;Hello, {log_source}.&quot;)
</span><del>-        stuff = twistedLogging.textFromEventDict(log.eventDict)
</del><ins>+
+        self.assertIn(&quot;log_source&quot;, log.event)
+        self.assertEquals(log.event[&quot;log_source&quot;], obj)
+
+        stuff = log.formatEvent(log.event)
</ins><span class="cx">         self.assertIn(&quot;Hello, &lt;LogComposedObject hello&gt;.&quot;, stuff)
</span><span class="cx"> 
</span><span class="cx"> 
</span><span class="lines">@@ -152,23 +164,22 @@
</span><span class="cx">             self.assertEquals(log.emitted[&quot;kwargs&quot;][&quot;junk&quot;], message)
</span><span class="cx"> 
</span><span class="cx">             if log.willLogAtLevel(level):
</span><del>-                #self.assertEquals(log.eventDict[&quot;log_format&quot;], format) # FIXME: doesn't work due to emit() mangling the format
-                self.assertEquals(log.eventDict[&quot;log_level&quot;], level)
-                self.assertEquals(log.eventDict[&quot;log_levelName&quot;], level.name)
-                self.assertEquals(log.eventDict[&quot;log_namespace&quot;], __name__)
-                self.assertEquals(log.eventDict[&quot;log_source&quot;], None)
</del><ins>+                self.assertEquals(log.event[&quot;log_format&quot;], format)
+                self.assertEquals(log.event[&quot;log_level&quot;], level)
+                self.assertEquals(log.event[&quot;log_namespace&quot;], __name__)
+                self.assertEquals(log.event[&quot;log_source&quot;], None)
</ins><span class="cx"> 
</span><del>-                self.assertEquals(log.eventDict[&quot;logLevel&quot;], pythonLogLevelMapping[level])
</del><ins>+                self.assertEquals(log.event[&quot;logLevel&quot;], pythonLogLevelMapping[level])
</ins><span class="cx"> 
</span><del>-                self.assertEquals(log.eventDict[&quot;junk&quot;], message)
</del><ins>+                self.assertEquals(log.event[&quot;junk&quot;], message)
</ins><span class="cx"> 
</span><span class="cx">                 # FIXME: this checks the end of message because we do formatting in emit()
</span><span class="cx">                 self.assertEquals(
</span><del>-                    twistedLogging.textFromEventDict(log.eventDict)[-len(message):],
</del><ins>+                    log.formatEvent(log.event),
</ins><span class="cx">                     message
</span><span class="cx">                 )
</span><span class="cx">             else:
</span><del>-                self.assertFalse(hasattr(log, &quot;eventDict&quot;))
</del><ins>+                self.assertFalse(hasattr(log, &quot;event&quot;))
</ins><span class="cx"> 
</span><span class="cx"> 
</span><span class="cx">     def test_defaultFailure(self):
</span><span class="lines">@@ -203,19 +214,16 @@
</span><span class="cx">             &quot;*&quot;,
</span><span class="cx">             log_format = &quot;#&quot;,
</span><span class="cx">             log_level = LogLevel.error,
</span><del>-            log_levelName = &quot;*level name*&quot;,
</del><span class="cx">             log_namespace = &quot;*namespace*&quot;,
</span><span class="cx">             log_source = &quot;*source*&quot;,
</span><span class="cx">         )
</span><span class="cx"> 
</span><span class="cx">         # FIXME: Should conflicts log errors?
</span><span class="cx"> 
</span><del>-        self.assertNotEquals(log.eventDict[&quot;log_format&quot;], &quot;*&quot;)
-        self.assertNotEquals(log.eventDict[&quot;log_format&quot;], &quot;#&quot;)
-        self.assertEquals(log.eventDict[&quot;log_level&quot;], LogLevel.warn)
-        self.assertEquals(log.eventDict[&quot;log_levelName&quot;], LogLevel.warn.name)
-        self.assertEquals(log.eventDict[&quot;log_namespace&quot;], log.namespace)
-        self.assertEquals(log.eventDict[&quot;log_source&quot;], None)
</del><ins>+        self.assertEquals(log.event[&quot;log_format&quot;], &quot;*&quot;)
+        self.assertEquals(log.event[&quot;log_level&quot;], LogLevel.warn)
+        self.assertEquals(log.event[&quot;log_namespace&quot;], log.namespace)
+        self.assertEquals(log.event[&quot;log_source&quot;], None)
</ins><span class="cx"> 
</span><span class="cx"> 
</span><span class="cx">     def test_defaultLogLevel(self):
</span><span class="lines">@@ -342,6 +350,22 @@
</span><span class="cx">         self.assertEquals(len(errors), 1)
</span><span class="cx"> 
</span><span class="cx"> 
</span><ins>+    def test_formatEvent(self):
+        &quot;&quot;&quot;
+        Test formatting.
+        &quot;&quot;&quot;
+        def formatEvent(log_format, **event):
+            event[&quot;log_format&quot;] = log_format
+            result = Logger.formatEvent(event)
+            self.assertIdentical(type(result), unicode) # Always returns unicode
+            return result
+
+        self.assertEquals(&quot;&quot;, formatEvent(&quot;&quot;))
+        self.assertEquals(&quot;abc&quot;, formatEvent(&quot;{x}&quot;, x=&quot;abc&quot;))
+        self.assertEquals(u'S\xe1nchez', formatEvent(&quot;S\xc3\xa1nchez&quot;)) # bytes-&gt;unicode
+        self.assertIn(&quot;Unable to format event&quot;, formatEvent(&quot;S\xe1nchez&quot;)) # Non-UTF-8 bytes
+
+
</ins><span class="cx">     def test_legacy_msg(self):
</span><span class="cx">         &quot;&quot;&quot;
</span><span class="cx">         Test LegacyLogger's log.msg()
</span></span></pre>
</div>
</div>

</body>
</html>