Merge lp:~allenap/maas/normalise-logging--bug-1639182--yakkety into lp:~maas-committers/maas/trunk

[Gavin Panella]

Log consistently on both Xenial and Yakkety.

Twisted is going through a transition and some of the work done in Xenial for Twisted 16.0 does not have the desired effect in Yakkety with Twisted 16.4, and vice-versa.

This must be read with a corresponding packaging change in
lp:~allenap/maas/packaging.normalise-logging--bug-1639182--yakkety.

[Blake Rouse (blake-rouse)]

Looks good.

review: Approve

[Andres Rodriguez (andreserl)]

I think we need to backport this to 2.1 too ?

On Mon, Nov 28, 2016 at 9:48 AM, Blake Rouse <email address hidden>
wrote:

> Review: Approve
>
> Looks good.
>
> Diff comments:
>
> >
> > === modified file 'services/regiond2/run'
> > --- services/regiond2/run 2016-06-22 17:03:02 +0000
> > +++ services/regiond2/run 2016-11-08 16:20:29 +0000
> > @@ -33,4 +33,6 @@
> >
> > # Exec the MAAS API and Web UI Server.
> > script="$(readlink -f bin/twistd.region)"
> > -exec "${script}" --nodaemon --pidfile="" maas-regiond
> > +exec "${script}" \
> > + --logger=provisioningserver.logger.EventLogger \
>
> This made it much easier to connect a custom logger. Less monkey patching
> is always good.
>
> > + --nodaemon --pidfile="" maas-regiond
>
>
> --
> https://code.launchpad.net/~allenap/maas/normalise-
> logging--bug-1639182--yakkety/+merge/310330
> Your team MAAS Committers is subscribed to branch lp:maas.
>

--
Andres Rodriguez
Engineering Manager, MAAS
Canonical USA, Inc.

[Blake Rouse (blake-rouse)]

Yes.

=== modified file 'services/rackd/run'
--- services/rackd/run	2016-03-31 23:34:55 +0000
+++ services/rackd/run	2016-11-08 16:20:29 +0000
@@ -30,4 +30,5 @@
 script="$(readlink -f bin/twistd.rack)"
 
 exec $(command -v authbind && echo --deep) \
-    "${script}" --nodaemon --pidfile="" maas-rackd
+    "${script}" --logger=provisioningserver.logger.EventLogger \
+    --nodaemon --pidfile="" maas-rackd

=== modified file 'services/regiond/run'
--- services/regiond/run	2016-06-22 17:03:02 +0000
+++ services/regiond/run	2016-11-08 16:20:29 +0000
@@ -33,4 +33,6 @@
 
 # Exec the MAAS API and Web UI Server.
 script="$(readlink -f bin/twistd.region)"
-exec "${script}" --nodaemon --pidfile="" maas-regiond
+exec "${script}" \
+    --logger=provisioningserver.logger.EventLogger \
+    --nodaemon --pidfile="" maas-regiond

=== modified file 'services/regiond2/run'
--- services/regiond2/run	2016-06-22 17:03:02 +0000
+++ services/regiond2/run	2016-11-08 16:20:29 +0000
@@ -33,4 +33,6 @@
 
 # Exec the MAAS API and Web UI Server.
 script="$(readlink -f bin/twistd.region)"
-exec "${script}" --nodaemon --pidfile="" maas-regiond
+exec "${script}" \
+    --logger=provisioningserver.logger.EventLogger \
+    --nodaemon --pidfile="" maas-regiond

=== modified file 'src/provisioningserver/logger/__init__.py'
--- src/provisioningserver/logger/__init__.py	2016-11-04 08:58:00 +0000
+++ src/provisioningserver/logger/__init__.py	2016-11-08 16:20:29 +0000
@@ -50,6 +50,7 @@
 
 __all__ = [
     "configure",
+    "EventLogger",
     "get_maas_logger",
     "LegacyLogger",
     "LoggingMode",
@@ -71,6 +72,7 @@
 from provisioningserver.logger._tftp import configure_tftp_logging
 from provisioningserver.logger._twisted import (
     configure_twisted_logging,
+    EventLogger,
     LegacyLogger,
     set_twisted_verbosity,
     VerbosityOptions,
@@ -146,6 +148,7 @@
     for verbosity_setter in verbosity_setters:
         verbosity_setter(verbosity)
 
+
 verbosity_setters = [
     set_standard_verbosity,
     set_twisted_verbosity,

=== modified file 'src/provisioningserver/logger/_twisted.py'
--- src/provisioningserver/logger/_twisted.py	2016-11-07 20:51:43 +0000
+++ src/provisioningserver/logger/_twisted.py	2016-11-08 16:20:29 +0000
@@ -5,6 +5,7 @@
 
 __all__ = [
     "configure_twisted_logging",
+    "EventLogger",
     "LegacyLogger",
     "VerbosityOptions",
 ]
@@ -29,7 +30,6 @@
     log as twistedLegacy,
     usage,
 )
-from twisted.python.util import untilConcludes
 
 # Map verbosity numbers to `twisted.logger` levels.
 DEFAULT_TWISTED_VERBOSITY_LEVELS = {
@@ -46,18 +46,6 @@
         "Twisted verbosity map does not match expectations.")
 
 
-# Those levels for which we should emit log events.
-_filterByLevels = frozenset()
-
-
-def _filterByLevel(event):
-    """Only log if event's level is in `_filterByLevels`."""
-    if event.get("log_level") in _filterByLevels:
-        return twistedModern.PredicateResult.maybe
-    else:
-        return twistedModern.PredicateResult.no
-
-
 @typed
 def set_twisted_verbosity(verbosity: int):
     """Reconfigure verbosity of the standard library's `logging` module."""
@@ -83,31 +71,9 @@
     """
     set_twisted_verbosity(verbosity)
 
-    # A list of markers for noise.
-    noisy = (
-        {"log_system": "-", "log_text": "Log opened."},
-        {"log_system": "-", "log_text": "Main loop terminated."},
-    )
-
-    def filterByNoise(event, noisy=noisy):
-        """Only log if event is not noisy."""
-        for noise in noisy:
-            if all(key in event and event[key] == noise[key] for key in noise):
-                return twistedModern.PredicateResult.no
-        else:
-            return twistedModern.PredicateResult.maybe
-
-    predicates = _filterByLevel, filterByNoise
-
-    # When `twistd` starts the reactor it initialises the legacy logging
-    # system. Intercept this to wrap the observer in a level filter. We can
-    # use this same approach when not running under `twistd` too.
-    def startLoggingWithObserver(observer, setStdout=1):
-        observer = twistedModern.FilteringLogObserver(observer, predicates)
-        reallyStartLoggingWithObserver(observer, setStdout)
-
-    reallyStartLoggingWithObserver = twistedLegacy.startLoggingWithObserver
-    twistedLegacy.startLoggingWithObserver = startLoggingWithObserver
+    warn_unless(hasattr(twistedLegacy, "startLoggingWithObserver"), (
+        "No startLoggingWithObserver function found; please investigate!"))
+    twistedLegacy.startLoggingWithObserver = _startLoggingWithObserver
 
     # Customise warnings behaviour. Ensure that nothing else — neither the
     # standard library's `logging` module nor Django — clobbers this later.
@@ -120,17 +86,6 @@
         twistedModern.globalLogBeginner.showwarning = warnings.showwarning
         twistedLegacy.theLogPublisher.showwarning = warnings.showwarning
 
-    # Globally override Twisted's legacy logging format.
-    warn_unless(hasattr(twistedLegacy, "FileLogObserver"), (
-        "No t.p.log.FileLogObserver attribute found; please investigate!"))
-    LegacyFileLogObserver.install()
-
-    # Install a wrapper so that log events from `t.logger` are logged with a
-    # namespace and level by the legacy logger in `t.python.log`. This needs
-    # to be injected into the `t.p.log` module in order to process events as
-    # they move from the legacy to the modern systems.
-    LegacyLogObserverWrapper.install()
-
     # Prevent `crochet` from initialising Twisted's logging.
     warn_unless(hasattr(crochet._main, "_startLoggingWithObserver"), (
         "No _startLoggingWithObserver function found; please investigate!"))
@@ -155,81 +110,77 @@
     # the original standard out stream when this process was started. This
     # bypasses any wrapping or redirection that may have been done elsewhere.
     if mode == LoggingMode.COMMAND:
-        twistedLegacy.startLogging(sys.__stdout__, setStdout=False)
-
-
-class LegacyFileLogObserver(twistedLegacy.FileLogObserver):
-    """Log legacy/mixed events to a file, formatting the MAAS way."""
-
-    timeFormat = DEFAULT_LOG_FORMAT_DATE
-    lineFormat = DEFAULT_LOG_FORMAT + "\n"
-
-    @classmethod
-    def install(cls):
-        """Install this wrapper in place of `log.FileLogObserver`."""
-        twistedLegacy.FileLogObserver = cls
-
-    def emit(self, event):
-        """Format and write out the given `event`."""
-        text = twistedLegacy.textFromEventDict(event)
-        if text is None:
-            return
-
-        system = event["system"] if "system" in event else None
-        if system is None and "log_namespace" in event:
-            system = event["log_namespace"]
-        # Logs written directly to `t.p.log.logfile` and `.logerr` get a
-        # namespace of "twisted.python.log". This is not interesting.
-        if system == twistedLegacy.__name__:
-            system = None
-
-        level = event["log_level"] if "log_level" in event else None
-        if level is None:
-            if "isError" in event and event["isError"]:
-                level = twistedModern.LogLevel.critical
-            else:
-                level = twistedModern.LogLevel.info
-
-        line = twistedLegacy._safeFormat(self.lineFormat, {
-            "asctime": self.formatTime(event["time"]),
-            "levelname": "-" if level is None else level.name,
-            "message": text.replace("\n", "\n\t"),
-            "name": "-" if system is None else system,
-        })
-
-        untilConcludes(self.write, line)
-        untilConcludes(self.flush)
-
-
-class LegacyLogObserverWrapper(twistedModern.LegacyLogObserverWrapper):
-    """Ensure that `log_system` is set in the event.
-
-    A newly populated `log_system` value is seen by `LegacyLogObserverWrapper`
-    (the superclass) and copied into the `system` key, later used when emitting
-    formatted log lines.
-    """
-
-    @classmethod
-    def install(cls):
-        """Install this wrapper in place of `log.LegacyLogObserverWrapper`.
-
-        Inject this wrapper into the `t.python.log` module then remove and
-        re-add all the legacy observers so that they're re-wrapped.
-        """
-        twistedLegacy.LegacyLogObserverWrapper = cls
-        for observer in twistedLegacy.theLogPublisher.observers:
-            twistedLegacy.theLogPublisher.removeObserver(observer)
-            twistedLegacy.theLogPublisher.addObserver(observer)
-
-    def __call__(self, event):
-        # Be defensive: `system` could be missing or could have a value of
-        # None. Same goes for `log_system` and `log_namespace`.
-        if event.get("system") is None and event.get("log_system") is None:
-            namespace = event.get("log_namespace")
-            if namespace is not None:
-                event["log_system"] = namespace
-        # Up-call, which will apply some more transformations.
-        return super().__call__(event)
+        twistedModern.globalLogBeginner.beginLoggingTo(
+            [EventLogger()], discardBuffer=False, redirectStandardIO=False)
+
+
+def EventLogger(outFile=sys.__stdout__):
+    """Factory returning a `t.logger.ILogObserver`.
+
+    This logs to the real standard out using MAAS's logging conventions.
+
+    Refer to this with `twistd`'s `--logger` argument.
+    """
+    return twistedModern.FilteringLogObserver(
+        twistedModern.FileLogObserver(outFile, _formatModernEvent),
+        (_filterByLevel, _filterByNoise))
+
+
+def _startLoggingWithObserver(observer, setStdout=1):
+    """Replacement for `t.p.log.startLoggingWithObserver`.
+
+    When `twistd` starts in 16.0 it initialises the legacy logging system.
+    Intercept this to DTRT with either a modern or legacy observer.
+
+    In Xenial (with Twisted 16.0) `observer` is probably a legacy observer,
+    like twisted.python.log.FileLogObserver, but we should check if it's
+    modern. In either case we should call through to the `globalLogBeginner`
+    ourselves. In Yakkety (with Twisted 16.4) this function will not be
+    called; `t.application.app.AppLogger` does the right thing already.
+    """
+    if not twistedModern.ILogObserver.providedBy(observer):
+        observer = twistedModern.LegacyLogObserverWrapper(observer)
+    twistedModern.globalLogBeginner.beginLoggingTo(
+        [observer], discardBuffer=False, redirectStandardIO=bool(setStdout))
+
+
+_timeFormat = DEFAULT_LOG_FORMAT_DATE
+_lineFormat = DEFAULT_LOG_FORMAT + "\n"
+
+
+def _formatModernEvent(event):
+    """Format a "modern" event according to MAAS's conventions."""
+    text = twistedModern.formatEvent(event)
+    time = event["log_time"] if "log_time" in event else None
+    level = event["log_level"] if "log_level" in event else None
+    system = event["log_system"] if "log_system" in event else None
+    if system is None and "log_namespace" in event:
+        system = _getSystemName(event["log_namespace"])
+
+    return _lineFormat % {
+        "asctime": twistedModern.formatTime(time, _timeFormat),
+        "levelname": "-" if level is None else level.name,
+        "message": "-" if text is None else text.replace("\n", "\n\t"),
+        "name": "-" if system is None else system,
+    }
+
+
+def _getSystemName(system):
+    """Return the "public" parts of `system`.
+
+    `system` is a dot-separated name, e.g. a fully-qualified module name. This
+    returns the leading parts of that name that are not pseudo-private, i.e.
+    that start with an underscore. For example "a.b._c.d" would be transformed
+    into "a.b".
+    """
+    if system is None:
+        return None
+    elif len(system) == 0:
+        return None
+    elif system.startswith("_"):
+        return None
+    else:
+        return system.split("._")[0]
 
 
 class LegacyLogger(twistedModern.Logger):
@@ -352,6 +303,33 @@
             pass  # We tried.
 
 
+# Those levels for which we should emit log events.
+_filterByLevels = frozenset()
+
+
+def _filterByLevel(event):
+    """Only log if event's level is in `_filterByLevels`."""
+    if event.get("log_level") in _filterByLevels:
+        return twistedModern.PredicateResult.maybe
+    else:
+        return twistedModern.PredicateResult.no
+
+# A list of markers for noise.
+_filterByNoises = (
+    {"log_namespace": "log_legacy", "log_text": "Log opened."},
+    {"log_namespace": "log_legacy", "log_text": "Main loop terminated."},
+)
+
+
+def _filterByNoise(event):
+    """Only log if event is not noisy."""
+    for noise in _filterByNoises:
+        if all(key in event and event[key] == noise[key] for key in noise):
+            return twistedModern.PredicateResult.no
+    else:
+        return twistedModern.PredicateResult.maybe
+
+
 _observe_twisted_internet_tcp_noise = re.compile(
     r"^(?:[(].+ Port \d+ Closed[)]|.+ starting on \d+)")
 
@@ -375,7 +353,7 @@
 
 
 _observe_twisted_internet_unix_noise = re.compile(
-    r"^(?:[(]Port \d+ Closed[)]|.+ starting on .+)")
+    r"^(?:[(]Port .+ Closed[)]|.+ starting on .+)")
 
 
 def observe_twisted_internet_unix(event):

=== modified file 'src/provisioningserver/logger/testing/__init__.py'
--- src/provisioningserver/logger/testing/__init__.py	2016-10-26 09:12:47 +0000
+++ src/provisioningserver/logger/testing/__init__.py	2016-11-08 16:20:29 +0000
@@ -4,6 +4,7 @@
 """Testing helpers for `provisioningserver.logger`."""
 
 __all__ = [
+    "find_log_lines",
     "make_event",
     "make_log_text",
     "pick_log_level",
@@ -11,20 +12,23 @@
 ]
 
 import random
+import re
 import time
 
 from maastesting.factory import factory
 from twisted.logger import LogLevel
 
 
-def make_event(log_text=None, log_level=None, log_time=None):
+def make_event(log_text=None, log_level=None, log_time=None, **other):
     """Make a minimal event dict for use with Twisted."""
-    return {
+    event = {
         "log_format": "{log_text}",
         "log_level": pick_log_level() if log_level is None else log_level,
         "log_text": make_log_text() if log_text is None else log_text,
         "log_time": pick_log_time() if log_time is None else log_time,
     }
+    event.update(other)
+    return event
 
 
 def make_log_text():
@@ -43,3 +47,20 @@
 def pick_log_time(noise=float(60 * 60)):
     """Pick a random time based on now, but with some noise."""
     return time.time() + (random.random() * noise) - (noise / 2)
+
+
+# Matches lines like: 2016-10-18 14:23:55 namespace: [level] message
+find_log_lines_re = re.compile(
+    r"^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}) (.*?): [[](.*)[]] (.*)$",
+    re.MULTILINE)
+
+
+def find_log_lines(text):
+    """Find logs in `text` that match `find_log_lines_re`.
+
+    Checks for well-formed date/times but throws them away.
+    """
+    return [
+        (ns, level, line) for (ts, ns, level, line) in
+        find_log_lines_re.findall(text)
+    ]

=== modified file 'src/provisioningserver/logger/testing/logsomething.py'
--- src/provisioningserver/logger/testing/logsomething.py	2016-11-04 00:11:06 +0000
+++ src/provisioningserver/logger/testing/logsomething.py	2016-11-08 16:20:29 +0000
@@ -46,9 +46,12 @@
 if options.set_verbosity is not None:
     provisioningserver.logger.set_verbosity(options.set_verbosity)
 
-# Simulate what `twistd` does when passed `--logfile=-`.
+# Simulate what `twistd` does when passed `--logger=...` in Twisted 16.0. In
+# 16.4 something similar happens, but globalLogBeginner.beginLoggingTo() is
+# called without going via `twisted.python.log`.
 if options.mode == modes.TWISTD:
-    twisted.python.log.startLogging(sys.stdout)
+    emitter = provisioningserver.logger.EventLogger()
+    twisted.python.log.startLoggingWithObserver(emitter)
 
 # Twisted, new.
 twisted.logger.Logger(options.name).debug("From `twisted.logger`.")

=== modified file 'src/provisioningserver/logger/tests/test__twisted.py'
--- src/provisioningserver/logger/tests/test__twisted.py	2016-11-07 13:37:33 +0000
+++ src/provisioningserver/logger/tests/test__twisted.py	2016-11-08 16:20:29 +0000
@@ -5,31 +5,30 @@
 
 __all__ = []
 
-from functools import partial
 import io
-from unittest.mock import (
-    patch,
-    sentinel,
-)
 
 from maastesting.factory import factory
-from maastesting.matchers import DocTestMatches
 from maastesting.testcase import MAASTestCase
 from maastesting.twisted import TwistedLoggerFixture
+from provisioningserver.logger import _twisted
+from provisioningserver.logger._common import DEFAULT_LOG_FORMAT_DATE
 from provisioningserver.logger._twisted import (
-    LegacyFileLogObserver,
+    _formatModernEvent,
+    _getSystemName,
+    EventLogger,
     LegacyLogger,
-    LegacyLogObserverWrapper,
     observe_twisted_internet_tcp,
     observe_twisted_internet_udp,
     observe_twisted_internet_unix,
 )
-from provisioningserver.logger.testing import make_event
+from provisioningserver.logger.testing import (
+    find_log_lines,
+    make_event,
+    pick_log_time,
+)
 from testtools.matchers import (
     AfterPreprocessing,
-    AllMatch,
     Contains,
-    ContainsAll,
     ContainsDict,
     Equals,
     HasLength,
@@ -37,11 +36,8 @@
     IsInstance,
     MatchesAll,
     MatchesDict,
-    MatchesSetwise,
-    Not,
 )
 from twisted import logger
-from twisted.python import log
 from twisted.python.failure import Failure
 
 
@@ -50,243 +46,6 @@
         {key: Equals(value) for key, value in expected.items()})
 
 
-def setLegacyObservers(observers):
-    """Remove existing legacy log observers, add those given."""
-    for observer in log.theLogPublisher.observers:
-        log.theLogPublisher.removeObserver(observer)
-    for observer in observers:
-        log.theLogPublisher.addObserver(observer)
-
-
-class TestLegacyFileLogObserver(MAASTestCase):
-    """Scenario tests for `LegacyFileLogObserver`."""
-
-    scenarios = tuple(
-        (log_level.name, dict(log_level=log_level))
-        for log_level in logger.LogLevel.iterconstants()
-    )
-
-    def test__namespace_and_level_is_printed_in_legacy_log(self):
-        # Restore existing observers at the end. This must be careful with
-        # ordering of clean-ups, hence the use of unittest.mock.patch.object
-        # as a context manager.
-        self.addCleanup(setLegacyObservers, log.theLogPublisher.observers)
-        # The global non-legacy `LogBeginner` emits critical messages straight
-        # to stderr, so temporarily put aside its observer to avoid seeing the
-        # critical log messages we're going to generate.
-        self.patch(logger.globalLogPublisher, "_observers", [])
-
-        logbuffer = io.StringIO()
-        observer = LegacyFileLogObserver(logbuffer)
-        observer.formatTime = lambda when: "<timestamp>"
-
-        oldlog = log.msg
-        # Deliberately use the default global observer in the new logger
-        # because we want to see how it behaves in a typical environment where
-        # logs are being emitted by the legacy logging infrastructure, for
-        # example running under `twistd`.
-        newlog = partial(logger.Logger().emit, self.log_level)
-
-        with patch.object(
-                log, "LegacyLogObserverWrapper",
-                log.LegacyLogObserverWrapper):
-            setLegacyObservers([observer.emit])
-            oldlog("Message from legacy", system="legacy")
-            newlog("Message from modern", log_system="modern")
-
-        self.assertThat(
-            logbuffer.getvalue(), DocTestMatches("""\
-            <timestamp> legacy: [info] Message from legacy
-            <timestamp> modern: [%s] Message from modern
-            """ % self.log_level.name))
-
-
-class TestLegacyFileLogObserver_Other(MAASTestCase):
-    """Other tests for `LegacyFileLogObserver`."""
-
-    def test__namespace_is_not_emitted_via_logfile_logerr(self):
-        # Restore existing observers at the end. This must be careful with
-        # ordering of clean-ups, hence the use of unittest.mock.patch.object
-        # as a context manager.
-        self.addCleanup(setLegacyObservers, log.theLogPublisher.observers)
-        # The global non-legacy `LogBeginner` emits critical messages straight
-        # to stderr, so temporarily put aside its observer to avoid seeing the
-        # critical log messages we're going to generate.
-        self.patch(logger.globalLogPublisher, "_observers", [])
-
-        logbuffer = io.StringIO()
-        observer = LegacyFileLogObserver(logbuffer)
-        observer.formatTime = lambda when: "<timestamp>"
-
-        with patch.object(
-                log, "LegacyLogObserverWrapper",
-                log.LegacyLogObserverWrapper):
-            setLegacyObservers([observer.emit])
-            log.logfile.write("Via log.logfile\n")
-            log.logerr.write("Via log.logerr\n")
-
-        self.assertThat(
-            logbuffer.getvalue(), DocTestMatches("""\
-            <timestamp> -: [info] Via log.logfile
-            <timestamp> -: [error] Via log.logerr
-            """))
-
-
-class TestLegacyLogObserverWrapper(MAASTestCase):
-    """Scenario tests for `LegacyLogObserverWrapper`."""
-
-    scenarios = tuple(
-        (log_level.name, dict(log_level=log_level))
-        for log_level in logger.LogLevel.iterconstants()
-    )
-
-    def processEvent(self, event):
-        events = []
-        observer = LegacyLogObserverWrapper(events.append)
-        observer(event)
-        self.assertThat(events, HasLength(1))
-        return events[0]
-
-    def test__adds_system_to_event(self):
-        self.assertThat(
-            # This is a `twisted.logger` event, not legacy, and requires
-            # values for `log_time` and `log_level` at a minimum.
-            self.processEvent({
-                "log_time": sentinel.log_time,
-                "log_level": self.log_level,
-            }),
-            MatchesAll(
-                Not(Contains("log_system")),
-                ContainsDictByEquality({"system": "-"}),
-            ),
-        )
-
-    def test__adds_log_system_and_system_to_event_with_namespace(self):
-        log_namespace = factory.make_name("log_namespace")
-        self.assertThat(
-            self.processEvent({
-                "log_time": sentinel.log_time,
-                "log_level": self.log_level,
-                "log_namespace": log_namespace,
-            }),
-            ContainsDictByEquality({
-                "log_system": log_namespace,
-                "system": log_namespace,
-            }),
-        )
-
-    def test__adds_system_to_legacy_event(self):
-        self.assertThat(
-            # This is a `twisted.python.log` event, i.e. legacy, and requires
-            # values for `time` and `isError` at a minimum.
-            self.processEvent({
-                "time": sentinel.time,
-                "isError": factory.pick_bool(),
-            }),
-            MatchesAll(
-                Not(Contains("log_system")),
-                ContainsDictByEquality({"system": "-"}),
-            ),
-        )
-
-    def test__preserves_log_system_in_event(self):
-        log_system = factory.make_name("log_system")
-        self.assertThat(
-            self.processEvent({
-                "log_time": sentinel.time,
-                "log_level": self.log_level,
-                "log_system": log_system,
-            }),
-            # `log_system` is not modified; `system` is set to match.
-            ContainsDictByEquality({
-                "log_system": log_system,
-                "system": log_system,
-            }),
-        )
-
-    def test__preserves_system_in_legacy_event(self):
-        system = factory.make_name("system")
-        self.assertThat(
-            self.processEvent({
-                "time": sentinel.time,
-                "isError": factory.pick_bool(),
-                "system": system,
-            }),
-            MatchesAll(
-                # `log_system` is not added when `system` already exists.
-                Not(Contains("log_system")),
-                ContainsDictByEquality({
-                    "system": system,
-                }),
-            ),
-        )
-
-
-class TestLegacyLogObserverWrapper_Installation(MAASTestCase):
-    """Tests for `LegacyLogObserverWrapper`."""
-
-    def setUp(self):
-        super().setUp()
-        # Restore existing observers at the end. Tests must be careful with
-        # ordering of clean-ups, hence the use of unittest.mock.patch.object
-        # as a context manager in the tests themselves.
-        self.addCleanup(setLegacyObservers, log.theLogPublisher.observers)
-
-    def test__installs_wrapper_to_log_module(self):
-        with patch.object(log, "LegacyLogObserverWrapper", sentinel.unchanged):
-            self.assertThat(
-                log.LegacyLogObserverWrapper,
-                Is(sentinel.unchanged))
-            LegacyLogObserverWrapper.install()
-            self.assertThat(
-                log.LegacyLogObserverWrapper,
-                Is(LegacyLogObserverWrapper))
-
-    def test__rewraps_existing_observers(self):
-
-        class OldWrapper:
-
-            def __init__(self, observer):
-                self.legacyObserver = observer
-
-            def __call__(self, event):
-                return self.legacyObserver(event)
-
-        with patch.object(log, "LegacyLogObserverWrapper", OldWrapper):
-
-            observers = (lambda event: event), (lambda event: event)
-            setLegacyObservers(observers)
-
-            # Our legacy observers are all registered.
-            self.assertThat(
-                log.theLogPublisher.observers,
-                MatchesSetwise(*map(Is, observers)))
-            # Behind the scenes they're all wrapped with OldWrapper.
-            self.assertThat(
-                log.theLogPublisher._legacyObservers,
-                AllMatch(IsInstance(OldWrapper)))
-            # They're registered with the new global log publisher too.
-            self.assertThat(
-                logger.globalLogPublisher._observers,
-                ContainsAll(log.theLogPublisher._legacyObservers))
-
-            # Install!
-            LegacyLogObserverWrapper.install()
-
-            # Our legacy observers are all still registered.
-            self.assertThat(
-                log.theLogPublisher.observers,
-                MatchesSetwise(*map(Is, observers)))
-            # Behind the scenes they're now all wrapped with our wrapper.
-            self.assertThat(
-                log.theLogPublisher._legacyObservers,
-                AllMatch(IsInstance(LegacyLogObserverWrapper)))
-            # They're registered with the new global log publisher too.
-            self.assertThat(
-                logger.globalLogPublisher._observers,
-                ContainsAll(log.theLogPublisher._legacyObservers))
-
-
 def formatTimeStatic(when):
     """Just return <when>."""
     return "<when>"
@@ -443,7 +202,7 @@
     """Tests for `observe_twisted_internet_unix`."""
 
     def test__ignores_port_closed_events(self):
-        event = make_event("(Port %d Closed)" % factory.pick_port())
+        event = make_event("(Port %r Closed)" % factory.make_name("port"))
         with TwistedLoggerFixture() as logger:
             observe_twisted_internet_unix(event)
         self.assertThat(logger.events, HasLength(0))
@@ -460,3 +219,193 @@
         with TwistedLoggerFixture() as logger:
             observe_twisted_internet_unix(event)
         self.assertThat(logger.events, Contains(event))
+
+
+class TestGetSystemName(MAASTestCase):
+    """Tests for `_getSystemName`."""
+
+    expectations = {
+        "foo.bar.baz": "foo.bar.baz",
+        "f_o.bar.baz": "f_o.bar.baz",
+        "foo.b_r.baz": "foo.b_r.baz",
+        "foo.bar.b_z": "foo.bar.b_z",
+        "foo.bar._az": "foo.bar",
+        "foo._ar.baz": "foo",
+        "foo._ar._az": "foo",
+        "_oo.bar.baz": None,
+        "_": None,
+        "": None,
+        None: None,
+    }
+
+    scenarios = tuple(
+        ("%s => %s" % (
+            string_in or repr(string_in),
+            string_out or repr(string_out)),
+         {"string_in": string_in, "string_out": string_out})
+        for string_in, string_out in expectations.items()
+    )
+
+    def test(self):
+        self.assertThat(
+            _getSystemName(self.string_in),
+            Equals(self.string_out))
+
+
+class TestFormatModernEvent(MAASTestCase):
+    """Tests for `_formatModernEvent`."""
+
+    scenarios = tuple(
+        (level.name, {"log_level": level})
+        for level in logger.LogLevel.iterconstants()
+    )
+
+    def test_format_basics(self):
+        thing1 = factory.make_name("thing")
+        thing2 = factory.make_name("thing")
+        log_system = factory.make_name("system")
+        log_format = ">{thing1}< >{thing2}<"
+        log_time = pick_log_time()
+        self.assertThat(
+            _formatModernEvent({
+                "log_time": log_time,
+                "log_format": log_format,
+                "log_system": log_system,
+                "log_level": self.log_level,
+                "thing1": thing1,
+                "thing2": thing2,
+            }),
+            Equals(
+                "%s %s: [%s] >%s< >%s<\n" % (
+                    logger.formatTime(log_time, DEFAULT_LOG_FORMAT_DATE),
+                    log_system, self.log_level.name, thing1, thing2),
+            ),
+        )
+
+    def test_formats_without_format(self):
+        self.assertThat(
+            _formatModernEvent({
+                "log_level": self.log_level,
+            }),
+            Equals("- -: [%s] \n" % self.log_level.name),
+        )
+
+    def test_formats_with_null_format(self):
+        self.assertThat(
+            _formatModernEvent({
+                "log_format": None,
+                "log_level": self.log_level,
+            }),
+            Equals("- -: [%s] \n" % self.log_level.name),
+        )
+
+    def test_formats_without_time(self):
+        self.assertThat(
+            _formatModernEvent({
+                "log_level": self.log_level,
+            }),
+            Equals("- -: [%s] \n" % self.log_level.name),
+        )
+
+    def test_formats_with_null_time(self):
+        self.assertThat(
+            _formatModernEvent({
+                "log_time": None,
+                "log_level": self.log_level,
+            }),
+            Equals("- -: [%s] \n" % self.log_level.name),
+        )
+
+    def test_uses_namespace_if_system_missing(self):
+        log_namespace = factory.make_name("namespace")
+        self.assertThat(
+            _formatModernEvent({
+                "log_level": self.log_level,
+                "log_namespace": log_namespace,
+            }),
+            Equals(
+                "- %s: [%s] \n" % (
+                    log_namespace, self.log_level.name),
+            ),
+        )
+
+    def test_uses_namespace_if_system_null(self):
+        log_namespace = factory.make_name("namespace")
+        self.assertThat(
+            _formatModernEvent({
+                "log_level": self.log_level,
+                "log_namespace": log_namespace,
+                "log_system": None,
+            }),
+            Equals(
+                "- %s: [%s] \n" % (
+                    log_namespace, self.log_level.name),
+            ),
+        )
+
+
+class TestEventLogger(MAASTestCase):
+    """Tests for `EventLogger`."""
+
+    scenarios = tuple(
+        (level.name, {"log_level": level})
+        for level in logger.LogLevel.iterconstants()
+    )
+
+    def setUp(self):
+        super(TestEventLogger, self).setUp()
+        self.output = io.StringIO()
+        self.log = EventLogger(self.output)
+        self.get_logs = lambda: find_log_lines(self.output.getvalue())
+
+    def setLogLevel(self, log_level):
+        """Set the level at which events will be logged.
+
+        This is not a minimum level, it is an absolute level.
+        """
+        self.patch(_twisted, "_filterByLevels", {self.log_level})
+
+    def test_basics(self):
+        self.setLogLevel(self.log_level)
+        event = make_event(log_level=self.log_level)
+        event["log_system"] = factory.make_name("system")
+        self.log(event)
+        self.assertSequenceEqual(
+            [(event["log_system"], self.log_level.name, event["log_text"])],
+            self.get_logs(),
+        )
+
+    def test_filters_by_level(self):
+        self.setLogLevel(self.log_level)
+        events = {
+            log_level: make_event(log_level=log_level)
+            for log_level in logger.LogLevel.iterconstants()
+        }
+        for event in events.values():
+            self.log(event)
+        # Only the log at the current level will get through.
+        self.assertSequenceEqual(
+            [("-", self.log_level.name, events[self.log_level]["log_text"])],
+            self.get_logs(),
+        )
+
+    def test_filters_by_noise(self):
+        self.setLogLevel(self.log_level)
+        common = dict(log_namespace="log_legacy", log_system="-")
+        noisy = [
+            make_event("Log opened.", **common),
+            make_event("Main loop terminated.", **common),
+        ]
+        for event in noisy:
+            self.log(event)
+        okay = [
+            make_event(log_level=self.log_level, **common),
+        ]
+        for event in okay:
+            self.log(event)
+        # Only the `okay` logs will get through.
+        expected = [
+            ("-", self.log_level.name, event["log_text"])
+            for event in okay
+        ]
+        self.assertSequenceEqual(expected, self.get_logs())

=== modified file 'src/provisioningserver/logger/tests/test_logger.py'
--- src/provisioningserver/logger/tests/test_logger.py	2016-11-07 13:37:33 +0000
+++ src/provisioningserver/logger/tests/test_logger.py	2016-11-08 16:20:29 +0000
@@ -6,7 +6,6 @@
 __all__ = []
 
 import pathlib
-import re
 import subprocess
 import sys
 
@@ -14,6 +13,7 @@
 from maastesting.matchers import DocTestMatches
 from maastesting.testcase import MAASTestCase
 from provisioningserver.logger import LoggingMode
+from provisioningserver.logger.testing import find_log_lines
 from provisioningserver.utils import typed
 from provisioningserver.utils.shell import select_c_utf8_locale
 from testtools.content import text_content
@@ -40,23 +40,6 @@
     return output.decode("utf-8")
 
 
-# Matches lines like: 2016-10-18 14:23:55 [namespace#level] message
-find_log_lines_re = re.compile(
-    r"^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}) (.*?): [[](.*)[]] (.*)$",
-    re.MULTILINE)
-
-
-def find_log_lines(text):
-    """Find logs in `text` that match `find_log_lines_re`.
-
-    Checks for well-formed date/times but throws them away.
-    """
-    return [
-        (ns, level, line) for (ts, ns, level, line) in
-        find_log_lines_re.findall(text)
-    ]
-
-
 class TestLogging(MAASTestCase):
     """Test logging in MAAS as configured by `p.logger.configure`.
 
@@ -115,7 +98,7 @@
             ('maas.' + name, 'error', 'From `get_maas_logger`.'),
             ('stdout', 'info', 'Printing to stdout.'),
             ('stderr', 'error', 'Printing to stderr.'),
-            ('__main__', 'warn', 'UserWarning: This is a warning!'),
+            ('-', 'warn', 'UserWarning: This is a warning!'),
         ]
         self.assertSequenceEqual(expected, observed)
 
@@ -143,7 +126,7 @@
             ('maas.' + name, 'error', 'From `get_maas_logger`.'),
             ('stdout', 'info', 'Printing to stdout.'),
             ('stderr', 'error', 'Printing to stderr.'),
-            ('__main__', 'warn', 'UserWarning: This is a warning!'),
+            ('-', 'warn', 'UserWarning: This is a warning!'),
         ]
         self.assertSequenceEqual(expected, observed)
 
@@ -163,7 +146,7 @@
             ('maas.' + name, 'warn', 'From `get_maas_logger`.'),
             ('maas.' + name, 'error', 'From `get_maas_logger`.'),
             ('stderr', 'error', 'Printing to stderr.'),
-            ('__main__', 'warn', 'UserWarning: This is a warning!'),
+            ('-', 'warn', 'UserWarning: This is a warning!'),
         ]
         self.assertSequenceEqual(expected, observed)