Merge lp:~allenap/maas/overhaul-logging-move-legacy-observer into lp:~maas-committers/maas/trunk

[Gavin Panella]

Move the customised legacy log observer into p.logger.

[Gavin Panella (allenap)]

This is a mechanical move, so self-reviewing. It comes after lp:~allenap/maas/overhaul-logging-more-01 which needs a full review so there's plenty of time to say something if you spot a problem.

review: Approve

=== modified file 'src/provisioningserver/logger/__init__.py'
--- src/provisioningserver/logger/__init__.py	2016-10-20 14:45:06 +0000
+++ src/provisioningserver/logger/__init__.py	2016-10-24 14:36:58 +0000
@@ -66,9 +66,9 @@
 
 import crochet
 from provisioningserver.config import is_dev_environment
+from provisioningserver.logger._twisted import LegacyLogObserverWrapper
 from provisioningserver.logger.log import get_maas_logger
 from provisioningserver.utils import typed
-from provisioningserver.utils.twisted import LegacyLogObserverWrapperForMAAS
 from twisted import logger as twistedModern
 from twisted.python import log as twistedLegacy
 import twisted.python.usage
@@ -236,7 +236,7 @@
     # 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.
-    LegacyLogObserverWrapperForMAAS.install()
+    LegacyLogObserverWrapper.install()
 
     # Prevent `crochet` from initialising Twisted's logging.
     warn_unless(hasattr(crochet._main, "_startLoggingWithObserver"), (

=== added file 'src/provisioningserver/logger/_twisted.py'
--- src/provisioningserver/logger/_twisted.py	1970-01-01 00:00:00 +0000
+++ src/provisioningserver/logger/_twisted.py	2016-10-24 14:36:58 +0000
@@ -0,0 +1,50 @@
+# Copyright 2016 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Twisted-specific logging stuff."""
+
+__all__ = [
+    'LegacyLogObserverWrapper',
+]
+
+from twisted import logger
+from twisted.python import log
+
+
+class LegacyLogObserverWrapper(logger.LegacyLogObserverWrapper):
+    """Ensure that `log_system` is set in the event.
+
+    This mimics what `twisted.logger.formatEventAsClassicLogText` does when
+    `log_system` is not set, and constructs it from `log_namespace` and
+    `log_level`.
+
+    This `log_system` value is then seen by `LegacyLogObserverWrapper` and
+    copied into the `system` key and then printed out in the logs by Twisted's
+    legacy logging (`t.python.log`) machinery. This still used by `twistd`, so
+    the net effect is that the logger's namespace and level are printed to the
+    `twistd` log.
+    """
+
+    @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.
+        """
+        log.LegacyLogObserverWrapper = cls
+        for observer in log.theLogPublisher.observers:
+            log.theLogPublisher.removeObserver(observer)
+            log.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`, `log_namespace`, and `log_level`.
+        if event.get("system") is None and event.get("log_system") is None:
+            namespace = event.get("log_namespace")
+            level = event.get("log_level")
+            event["log_system"] = "{namespace}#{level}".format(
+                namespace=("-" if namespace is None else namespace),
+                level=("-" if level is None else level.name))
+        # Up-call, which will apply some more transformations.
+        return super().__call__(event)

=== added file 'src/provisioningserver/logger/tests/test__twisted.py'
--- src/provisioningserver/logger/tests/test__twisted.py	1970-01-01 00:00:00 +0000
+++ src/provisioningserver/logger/tests/test__twisted.py	2016-10-24 14:36:58 +0000
@@ -0,0 +1,240 @@
+# Copyright 2014-2016 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Tests for Twisted-specific logging stuff."""
+
+__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 provisioningserver.logger._twisted import LegacyLogObserverWrapper
+from testtools.matchers import (
+    AllMatch,
+    Contains,
+    ContainsAll,
+    ContainsDict,
+    Equals,
+    HasLength,
+    Is,
+    IsInstance,
+    MatchesAll,
+    MatchesSetwise,
+    Not,
+)
+from twisted import logger
+from twisted.python import log
+
+
+def ContainsDictByEquality(expected):
+    return ContainsDict(
+        {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 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_log_system_and_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,
+            }),
+            ContainsDictByEquality({
+                "log_system": "-#" + self.log_level.name,
+                "system": "-#" + self.log_level.name,
+            }),
+        )
+
+    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 + "#" + self.log_level.name,
+                "system": log_namespace + "#" + self.log_level.name,
+            }),
+        )
+
+    def test__adds_log_system_and_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(),
+            }),
+            ContainsDictByEquality({
+                "log_system": "-#-",
+                "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,
+                }),
+            ),
+        )
+
+    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 = log.FileLogObserver(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("Before (legacy)")
+            newlog("Before (new)")
+            LegacyLogObserverWrapper.install()
+            oldlog("After (legacy)")
+            newlog("After (new)")
+
+        self.assertThat(
+            logbuffer.getvalue(), DocTestMatches("""\
+            <timestamp> [-] Before (legacy)
+            <timestamp> [-] Before (new)
+            <timestamp> [-] After (legacy)
+            <timestamp> [%s#%s] After (new)
+            """ % (__name__, self.log_level.name)))
+
+
+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))

=== modified file 'src/provisioningserver/monkey.py'
--- src/provisioningserver/monkey.py	2016-10-13 23:43:14 +0000
+++ src/provisioningserver/monkey.py	2016-10-24 14:36:58 +0000
@@ -327,12 +327,6 @@
         threads.deferToThreadPool = new_deferToThreadPool
 
 
-def install_twisted_legacy_log_observer_wrapper():
-    """Install `LegacyLogObserverWrapperForMAAS`."""
-    from provisioningserver.utils import twisted
-    twisted.LegacyLogObserverWrapperForMAAS.install()
-
-
 def add_patches_to_txtftp():
     add_term_error_code_to_tftp()
     fix_tftp_requests()
@@ -344,4 +338,3 @@
     fix_twisted_web_server_addressToTuple()
     fix_twisted_internet_tcp()
     augment_twisted_deferToThreadPool()
-    install_twisted_legacy_log_observer_wrapper()

=== modified file 'src/provisioningserver/utils/tests/test_twisted.py'
--- src/provisioningserver/utils/tests/test_twisted.py	2016-10-13 23:43:14 +0000
+++ src/provisioningserver/utils/tests/test_twisted.py	2016-10-24 14:36:58 +0000
@@ -24,7 +24,6 @@
 from unittest.mock import (
     ANY,
     Mock,
-    patch,
     sentinel,
 )
 
@@ -62,7 +61,6 @@
     FOREVER,
     IAsynchronous,
     ISynchronous,
-    LegacyLogObserverWrapperForMAAS,
     LONGTIME,
     makeDeferredWithProcessProtocol,
     pause,
@@ -79,10 +77,7 @@
 from testtools.deferredruntest import assert_fails_with
 from testtools.matchers import (
     AfterPreprocessing,
-    AllMatch,
     Contains,
-    ContainsAll,
-    ContainsDict,
     Equals,
     HasLength,
     Is,
@@ -90,13 +85,11 @@
     MatchesAll,
     MatchesException,
     MatchesListwise,
-    MatchesSetwise,
     MatchesStructure,
     Not,
     Raises,
 )
 from testtools.testcase import ExpectedException
-from twisted import logger
 from twisted.internet import reactor
 from twisted.internet.defer import (
     AlreadyCalledError,
@@ -118,7 +111,6 @@
 )
 from twisted.python import (
     context,
-    log,
     threadable,
 )
 from twisted.python.failure import Failure
@@ -1887,210 +1879,3 @@
         transport = Mock(pid=randrange(99999, 9999999))
         protocol.makeConnection(transport)
         self.assertThat(setpgid, MockCalledOnceWith(transport.pid, 0))
-
-
-def ContainsDictByEquality(expected):
-    return ContainsDict(
-        {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 TestLegacyLogObserverWrapperForMAAS(MAASTestCase):
-    """Scenario tests for `LegacyLogObserverWrapperForMAAS`."""
-
-    scenarios = tuple(
-        (log_level.name, dict(log_level=log_level))
-        for log_level in logger.LogLevel.iterconstants()
-    )
-
-    def processEvent(self, event):
-        events = []
-        observer = LegacyLogObserverWrapperForMAAS(events.append)
-        observer(event)
-        self.assertThat(events, HasLength(1))
-        return events[0]
-
-    def test__adds_log_system_and_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,
-            }),
-            ContainsDictByEquality({
-                "log_system": "-#" + self.log_level.name,
-                "system": "-#" + self.log_level.name,
-            }),
-        )
-
-    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 + "#" + self.log_level.name,
-                "system": log_namespace + "#" + self.log_level.name,
-            }),
-        )
-
-    def test__adds_log_system_and_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(),
-            }),
-            ContainsDictByEquality({
-                "log_system": "-#-",
-                "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,
-                }),
-            ),
-        )
-
-    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 = log.FileLogObserver(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("Before (legacy)")
-            newlog("Before (new)")
-            LegacyLogObserverWrapperForMAAS.install()
-            oldlog("After (legacy)")
-            newlog("After (new)")
-
-        self.assertThat(
-            logbuffer.getvalue(), DocTestMatches("""\
-            <timestamp> [-] Before (legacy)
-            <timestamp> [-] Before (new)
-            <timestamp> [-] After (legacy)
-            <timestamp> [%s#%s] After (new)
-            """ % (__name__, self.log_level.name)))
-
-
-class TestLegacyLogObserverWrapperForMAAS_Installation(MAASTestCase):
-    """Tests for `LegacyLogObserverWrapperForMAAS`."""
-
-    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))
-            LegacyLogObserverWrapperForMAAS.install()
-            self.assertThat(
-                log.LegacyLogObserverWrapper,
-                Is(LegacyLogObserverWrapperForMAAS))
-
-    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!
-            LegacyLogObserverWrapperForMAAS.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(LegacyLogObserverWrapperForMAAS)))
-            # They're registered with the new global log publisher too.
-            self.assertThat(
-                logger.globalLogPublisher._observers,
-                ContainsAll(log.theLogPublisher._legacyObservers))

=== modified file 'src/provisioningserver/utils/twisted.py'
--- src/provisioningserver/utils/twisted.py	2016-10-13 23:43:14 +0000
+++ src/provisioningserver/utils/twisted.py	2016-10-24 14:36:58 +0000
@@ -63,10 +63,7 @@
 from twisted.internet.error import ProcessDone
 from twisted.internet.protocol import ProcessProtocol
 from twisted.internet.threads import deferToThread
-from twisted.logger import (
-    LegacyLogObserverWrapper,
-    Logger,
-)
+from twisted.logger import Logger
 from twisted.python import (
     context,
     log,
@@ -1058,42 +1055,3 @@
                 _os_setpgid(self.transport.pid, 0)
             except ProcessLookupError:
                 pass  # Already exited.
-
-
-class LegacyLogObserverWrapperForMAAS(LegacyLogObserverWrapper):
-    """Ensure that `log_system` is set in the event.
-
-    This mimics what `twisted.logger.formatEventAsClassicLogText` does when
-    `log_system` is not set, and constructs it from `log_namespace` and
-    `log_level`.
-
-    This `log_system` value is then seen by `LegacyLogObserverWrapper` and
-    copied into the `system` key and then printed out in the logs by Twisted's
-    legacy logging (`t.python.log`) machinery. This still used by `twistd`, so
-    the net effect is that the logger's namespace and level are printed to the
-    `twistd` log.
-    """
-
-    @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.
-        """
-        log.LegacyLogObserverWrapper = cls
-        for observer in log.theLogPublisher.observers:
-            log.theLogPublisher.removeObserver(observer)
-            log.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`, `log_namespace`, and `log_level`.
-        if event.get("system") is None and event.get("log_system") is None:
-            namespace = event.get("log_namespace")
-            level = event.get("log_level")
-            event["log_system"] = "{namespace}#{level}".format(
-                namespace=("-" if namespace is None else namespace),
-                level=("-" if level is None else level.name))
-        # Up-call, which will apply some more transformations.
-        return super().__call__(event)