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

[Gavin Panella]

Change the logging format to be similar between regiond.log, rackd.log, and maas.log.

[Gavin Panella (allenap)]

This monkey-patches the legacy log emitter to use DEFAULT_LOG_FORMAT, so future changes to logging format will be easier.

Having said that... because we're in a transnational state in Twisted between the legacy and modern systems... this code completely doesn't have the intended effect in Twisted 16.4 (which is found in Yakkety).

[Blake Rouse (blake-rouse)]

Looks good. I tried to get this to work on Friday and was lost. I really dont think twisted could have made logging any more complicated.

This is good enough for the SRU to Xenial, but we need to get this fixes in yacketty as well. ETA on that, possible to do in the branch. So we can get it done in one pass. We need to release 2.1.1 today.

review: Needs Information

[Gavin Panella (allenap)]

> Looks good. I tried to get this to work on Friday and was lost. I
> really dont think twisted could have made logging any more
> complicated.

I'm right with you on this. My only hope for this is that it'll get a
lot simpler once t.p.log is gone.

> This is good enough for the SRU to Xenial, but we need to get this
> fixes in yacketty as well. ETA on that, possible to do in the branch.
> So we can get it done in one pass. We need to release 2.1.1 today.

I've been hitting my head against the wall with doing this in Yakkety.
I'll land this but we're just going to have to live with funny log for a
bit longer in Yakkety.

On the other hand, do we need to do this at all? The message format has
not changed through the recent logging changes. Do we actually need to
change it now before we can release?

[Blake Rouse (blake-rouse)]

Yes we need to get this correct before release of 2.1.1. As we are SRU'ing 2.1.1 to Xenial. Mark wants the SRU finished by the end of this week. So we need to release ASAP. This 2.1.1 will also require an SRU to yakketty so we should make this work in yakketty as well.

[Andres Rodriguez (andreserl)]

The format has changed between 2.1.0 and what will be 2.1.1. So I'm fine landing this for xenial and we will address it for yakkety afterwards.

We need to have a serious discussion how we can overall improve the logging system.

review: Approve

[Gavin Panella (allenap)]

> We need to have a serious discussion how we can overall improve the
> logging system.

Let me kick it off.

There has been pain in all parts of the stack: Django, Twisted, and the
standard library all do stupid things that we need to work around. I've
been able to contain the ugliness to the p.logger package.

The logs that Django and `logging` produce and those that Twisted
produce are integrated only when they hit the log file. Logs from one
subsystem are not shipped from `logging` to Twisted or vice-versa. There
is an adapter that can pipe Twisted's logs over to the standard library
but it's too lossy right now, and it's not clear that it'll help much
anyway.

Twisted has just one idea of what a log should look like. It doesn't
care about customising the textual output, though it does provide the
means to write your own log event[1] observer and so emit rot-13 logs to
a thermal printer on a pidgeon. It's neither right nor wrong, just a
different approach to that of the stdlib's `logging` package.

This bug in particular has been painful for a couple of reasons:

1. I'm trying to do it the "wrong" way with Twisted. When invoking a
   plugin via twistd the "right" way to customise logging output is to
   specify an observer via `--logger=fully.qualified.callable`.

2. As I've mentioned before, Twisted is in a transitional state between
   its "legacy" and "modern" logging subsystems. There's a lot of
   complexity behind the scenes to make this work, and significant
   change between Twisted in Xenial and Yakkety.

I've been trying to avoid #1 so far, to keep the details hidden, but no
longer. The changes between Twisted 16.0 (Xenial) and 16.4 (Yakkety)
means this is likely to be the only sane way to achieve what we want,
and this is what I'll work on now.

[1] A log *event* is a dict containing some standard keys and any number
of other pieces of information, passed between log observers. One such
observer might filter events, one might forward events to multiple
observers, one might format the event and write it out to a log file.

=== modified file 'src/provisioningserver/logger/_common.py'
--- src/provisioningserver/logger/_common.py	2016-10-28 15:58:32 +0000
+++ src/provisioningserver/logger/_common.py	2016-11-07 14:38:23 +0000
@@ -21,7 +21,7 @@
 
 # This format roughly matches Twisted's default, so that combined Twisted and
 # Django logs are consistent with one another.
-DEFAULT_LOG_FORMAT = "%(asctime)s [%(name)s#%(levelname)s] %(message)s"
+DEFAULT_LOG_FORMAT = "%(asctime)s %(name)s: [%(levelname)s] %(message)s"
 DEFAULT_LOG_FORMAT_DATE = "%Y-%m-%d %H:%M:%S"
 DEFAULT_LOG_VERBOSITY_LEVELS = {0, 1, 2, 3}
 DEFAULT_LOG_VERBOSITY = 2
 
=== modified file 'src/provisioningserver/logger/_twisted.py'
--- src/provisioningserver/logger/_twisted.py	2016-11-03 21:11:05 +0000
+++ src/provisioningserver/logger/_twisted.py	2016-11-07 14:38:23 +0000
@@ -15,6 +15,7 @@
 
 import crochet
 from provisioningserver.logger._common import (
+    DEFAULT_LOG_FORMAT,
     DEFAULT_LOG_FORMAT_DATE,
     DEFAULT_LOG_VERBOSITY,
     DEFAULT_LOG_VERBOSITY_LEVELS,
@@ -28,6 +29,7 @@
     log as twistedLegacy,
     usage,
 )
+from twisted.python.util import untilConcludes
 
 # Map verbosity numbers to `twisted.logger` levels.
 DEFAULT_TWISTED_VERBOSITY_LEVELS = {
@@ -117,12 +119,10 @@
         twistedModern.globalLogBeginner.showwarning = warnings.showwarning
         twistedLegacy.theLogPublisher.showwarning = warnings.showwarning
 
-    # Globally override Twisted's log date format. It's tricky to get to the
-    # FileLogObserver that twistd installs so that we can modify its config
-    # alone, but we actually do want to make a global change anyway.
-    warn_unless(hasattr(twistedLegacy.FileLogObserver, "timeFormat"), (
-        "No FileLogObserver.timeFormat attribute found; please investigate!"))
-    twistedLegacy.FileLogObserver.timeFormat = DEFAULT_LOG_FORMAT_DATE
+    # 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
@@ -157,18 +157,55 @@
         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.
 
-    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.
+    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
@@ -185,17 +222,11 @@
 
     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`.
+        # 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")
-            # Logs written directly to `t.p.log.logfile` and `.logerr` get a
-            # namespace of "twisted.python.log". This is not interesting.
-            if namespace == twistedLegacy.__name__:
-                namespace = None
-            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))
+            if namespace is not None:
+                event["log_system"] = namespace
         # Up-call, which will apply some more transformations.
         return super().__call__(event)
 
 
=== modified file 'src/provisioningserver/logger/tests/test__twisted.py'
--- src/provisioningserver/logger/tests/test__twisted.py	2016-11-02 10:01:16 +0000
+++ src/provisioningserver/logger/tests/test__twisted.py	2016-11-07 14:38:23 +0000
@@ -17,6 +17,7 @@
 from maastesting.testcase import MAASTestCase
 from maastesting.twisted import TwistedLoggerFixture
 from provisioningserver.logger._twisted import (
+    LegacyFileLogObserver,
     LegacyLogger,
     LegacyLogObserverWrapper,
     observe_twisted_internet_tcp,
@@ -57,6 +58,80 @@
         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`."""
 
@@ -72,7 +147,7 @@
         self.assertThat(events, HasLength(1))
         return events[0]
 
-    def test__adds_log_system_and_system_to_event(self):
+    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.
@@ -80,10 +155,10 @@
                 "log_time": sentinel.log_time,
                 "log_level": self.log_level,
             }),
-            ContainsDictByEquality({
-                "log_system": "-#" + self.log_level.name,
-                "system": "-#" + self.log_level.name,
-            }),
+            MatchesAll(
+                Not(Contains("log_system")),
+                ContainsDictByEquality({"system": "-"}),
+            ),
         )
 
     def test__adds_log_system_and_system_to_event_with_namespace(self):
@@ -95,12 +170,12 @@
                 "log_namespace": log_namespace,
             }),
             ContainsDictByEquality({
-                "log_system": log_namespace + "#" + self.log_level.name,
-                "system": log_namespace + "#" + self.log_level.name,
+                "log_system": log_namespace,
+                "system": log_namespace,
             }),
         )
 
-    def test__adds_log_system_and_system_to_legacy_event(self):
+    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.
@@ -108,10 +183,10 @@
                 "time": sentinel.time,
                 "isError": factory.pick_bool(),
             }),
-            ContainsDictByEquality({
-                "log_system": "-#-",
-                "system": "-#-",
-            }),
+            MatchesAll(
+                Not(Contains("log_system")),
+                ContainsDictByEquality({"system": "-"}),
+            ),
         )
 
     def test__preserves_log_system_in_event(self):
@@ -146,77 +221,6 @@
             ),
         )
 
-    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)))
-
-    def test__namespace_and_level_are_elided_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 = log.FileLogObserver(logbuffer)
-        observer.formatTime = lambda when: "<timestamp>"
-
-        with patch.object(
-                log, "LegacyLogObserverWrapper",
-                log.LegacyLogObserverWrapper):
-            setLegacyObservers([observer.emit])
-            log.logfile.write("Before (via log.logfile)\n")
-            log.logerr.write("Before (via log.logerr)\n")
-            LegacyLogObserverWrapper.install()
-            log.logfile.write("After (via log.logfile)\n")
-            log.logerr.write("After (via log.logerr)\n")
-
-        self.assertThat(
-            logbuffer.getvalue(), DocTestMatches("""\
-            <timestamp> [-] Before (via log.logfile)
-            <timestamp> [-] Before (via log.logerr)
-            <timestamp> [-#info] After (via log.logfile)
-            <timestamp> [-#error] After (via log.logerr)
-            """))
-
 
 class TestLegacyLogObserverWrapper_Installation(MAASTestCase):
     """Tests for `LegacyLogObserverWrapper`."""
 
=== modified file 'src/provisioningserver/logger/tests/test_logger.py'
--- src/provisioningserver/logger/tests/test_logger.py	2016-11-03 21:39:45 +0000
+++ src/provisioningserver/logger/tests/test_logger.py	2016-11-07 14:38:23 +0000
@@ -42,7 +42,7 @@
 
 # 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}) [[](.*?)(?:#(.*))?[]] (.*)$",
+    r"^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}) (.*?): [[](.*)[]] (.*)$",
     re.MULTILINE)
 
 
@@ -106,7 +106,7 @@
             (name, 'info', 'From `twisted.logger`.'),
             (name, 'warn', 'From `twisted.logger`.'),
             (name, 'error', 'From `twisted.logger`.'),
-            (name, '', 'From `twisted.python.log`.'),
+            (name, 'info', 'From `twisted.python.log`.'),
             (name, 'info', 'From `logging`.'),
             (name, 'warn', 'From `logging`.'),
             (name, 'error', 'From `logging`.'),
@@ -132,7 +132,7 @@
             (name, 'info', 'From `twisted.logger`.'),
             (name, 'warn', 'From `twisted.logger`.'),
             (name, 'error', 'From `twisted.logger`.'),
-            (name, '', 'From `twisted.python.log`.'),
+            (name, 'info', 'From `twisted.python.log`.'),
             (name, 'debug', 'From `logging`.'),
             (name, 'info', 'From `logging`.'),
             (name, 'warn', 'From `logging`.'),
@@ -195,7 +195,7 @@
             (name, 'info', 'From `twisted.logger`.'),
             (name, 'warn', 'From `twisted.logger`.'),
             (name, 'error', 'From `twisted.logger`.'),
-            (name, '', 'From `twisted.python.log`.'),
+            (name, 'info', 'From `twisted.python.log`.'),
             (name, 'info', 'From `logging`.'),
             (name, 'warn', 'From `logging`.'),
             (name, 'error', 'From `logging`.'),
@@ -224,7 +224,7 @@
             (name, 'info', 'From `twisted.logger`.'),
             (name, 'warn', 'From `twisted.logger`.'),
             (name, 'error', 'From `twisted.logger`.'),
-            (name, '', 'From `twisted.python.log`.'),
+            (name, 'info', 'From `twisted.python.log`.'),
             (name, 'debug', 'From `logging`.'),
             (name, 'info', 'From `logging`.'),
             (name, 'warn', 'From `logging`.'),