Merge lp:~allenap/maas/make-debug-logs-prettier--bug-1633696 into lp:~maas-committers/maas/trunk

[Gavin Panella]

Print "regiond" or "rackd" instead of "twisted.python.log" in log files.

[Blake Rouse (blake-rouse)]

Can you give an example of the difference?

review: Needs Information

[Gavin Panella (allenap)]

A log line like:

  2017-03-26 07:38:47 twisted.python.log: [info] ::ffff:192.168.1.3 - - [26/Mar/2017:06:38:46 +0000] "GET /MAAS/rpc/ HTTP/1.0" 200 208 "-" "provisioningserver.rpc.clusterservice.ClusterClientService"

will instead be:

  2017-03-26 07:38:47 regiond: [info] ::ffff:192.168.1.3 - - [26/Mar/2017:06:38:46 +0000] "GET /MAAS/rpc/ HTTP/1.0" 200 208 "-" "provisioningserver.rpc.clusterservice.ClusterClientService"

I am also, separately, making this log overall a bit shorter.

[Blake Rouse (blake-rouse)]

Nice! Love it!

review: Approve

=== modified file 'src/provisioningserver/logger/_twisted.py'
--- src/provisioningserver/logger/_twisted.py	2016-12-07 12:46:14 +0000
+++ src/provisioningserver/logger/_twisted.py	2017-03-30 13:04:30 +0000
@@ -10,6 +10,7 @@
     "VerbosityOptions",
 ]
 
+import os
 import re
 import sys
 import warnings
@@ -75,6 +76,11 @@
         "No startLoggingWithObserver function found; please investigate!"))
     twistedLegacy.startLoggingWithObserver = _startLoggingWithObserver
 
+    # Set the legacy `logfile` namespace according to the environment in which
+    # we guess we're running. This `logfile` is used primarily — in MAAS — by
+    # Twisted's HTTP server machinery for combined access logging.
+    twistedLegacy.logfile.log.namespace = _getCommandName(sys.argv)
+
     # Customise warnings behaviour. Ensure that nothing else — neither the
     # standard library's `logging` module nor Django — clobbers this later.
     warn_unless(warnings.showwarning.__module__ == warnings.__name__, (
@@ -183,6 +189,43 @@
         return system.split("._")[0]
 
 
+def _getCommandName(argv):
+    """Return a guess at the currently running command's name.
+
+    When running under `twistd`, it will return "regiond", "rackd", or
+    "daemon". The latter is unlikely to happen, but it's a safe default.
+
+    Otherwise it assumes a command is being run and tries to derive a name
+    from the script being run.
+    """
+    if any("twist" in arg for arg in argv):
+        if any("maas-regiond" in arg for arg in argv):
+            return "regiond"
+        elif any("maas-rackd" in arg for arg in argv):
+            return "rackd"
+        else:
+            # Return a safe default.
+            return "daemon"
+    else:
+        candidates = map(os.path.basename, argv)
+        try:
+            command = next(candidates)
+            if "python" in command:
+                command = next(candidates)
+        except StopIteration:
+            # Return a safe default.
+            return "command"
+        else:
+            if command.startswith("-"):
+                # It's probably a command-line option.
+                return "command"
+            elif command.endswith(".py"):
+                # Remove the .py suffix.
+                return command[:-3]
+            else:
+                return command
+
+
 class LegacyLogger(twistedModern.Logger):
     """Looks like a stripped-down `t.p.log` module, logs to a `Logger`.
 

=== modified file 'src/provisioningserver/logger/testing/logsomething.py'
--- src/provisioningserver/logger/testing/logsomething.py	2017-03-29 13:34:55 +0000
+++ src/provisioningserver/logger/testing/logsomething.py	2017-03-30 13:04:30 +0000
@@ -62,6 +62,8 @@
 
     # Twisted, legacy.
     twisted.python.log.msg("From `twisted.python.log`.", system=options.name)
+    # Twisted, legacy `logfile`. This has its own namespace.
+    twisted.python.log.logfile.write("From `twisted.python.log.logfile`.\n")
 
     # Standard library.
     logging.getLogger(options.name).debug("From `logging`.")

=== modified file 'src/provisioningserver/logger/tests/test__twisted.py'
--- src/provisioningserver/logger/tests/test__twisted.py	2016-12-07 12:46:14 +0000
+++ src/provisioningserver/logger/tests/test__twisted.py	2017-03-30 13:04:30 +0000
@@ -14,6 +14,7 @@
 from provisioningserver.logger._common import DEFAULT_LOG_FORMAT_DATE
 from provisioningserver.logger._twisted import (
     _formatModernEvent,
+    _getCommandName,
     _getSystemName,
     EventLogger,
     LegacyLogger,
@@ -252,6 +253,44 @@
             Equals(self.string_out))
 
 
+class TestGetCommandName(MAASTestCase):
+    """Tests for `_getCommandName`."""
+
+    expectations = {
+        # maas-rackd
+        ("/usr/bin/twistd3", "--nodaemon", "--pidfile=",
+         "--logger=provisioningserver.logger.EventLogger",
+         "maas-rackd"): "rackd",
+        # maas-regiond
+        ("twistd3", "--nodaemon", "--pidfile=",
+         "--logger=provisioningserver.logger.EventLogger",
+         "maas-regiond"): "regiond",
+        # twistd running ...
+        ("twistd3", "--an-option",
+         "something-else"): "daemon",
+        # command
+        ("some-command", ): "some-command",
+        # command with .py suffix
+        ("some-command-with-suffix.py", ): "some-command-with-suffix",
+        # command running under python
+        ("python", "py-command", ): "py-command",
+        # command running under python with .py suffix
+        ("python", "py-command-with-suffix.py", ): "py-command-with-suffix",
+        # something else
+        ("python", "-c", "print('woo')"): "command",
+    }
+
+    scenarios = tuple(
+        (expected, {"argv": argv, "expected": expected})
+        for argv, expected in expectations.items()
+    )
+
+    def test(self):
+        self.assertThat(
+            _getCommandName(self.argv),
+            Equals(self.expected))
+
+
 class TestFormatModernEvent(MAASTestCase):
     """Tests for `_formatModernEvent`."""
 

=== modified file 'src/provisioningserver/logger/tests/test_logger.py'
--- src/provisioningserver/logger/tests/test_logger.py	2016-12-07 12:46:14 +0000
+++ src/provisioningserver/logger/tests/test_logger.py	2017-03-30 13:04:30 +0000
@@ -90,6 +90,7 @@
             (name, 'warn', 'From `twisted.logger`.'),
             (name, 'error', 'From `twisted.logger`.'),
             (name, 'info', 'From `twisted.python.log`.'),
+            ('logsomething', 'info', 'From `twisted.python.log.logfile`.'),
             (name, 'info', 'From `logging`.'),
             (name, 'warn', 'From `logging`.'),
             (name, 'error', 'From `logging`.'),
@@ -116,6 +117,7 @@
             (name, 'warn', 'From `twisted.logger`.'),
             (name, 'error', 'From `twisted.logger`.'),
             (name, 'info', 'From `twisted.python.log`.'),
+            ('logsomething', 'info', 'From `twisted.python.log.logfile`.'),
             (name, 'debug', 'From `logging`.'),
             (name, 'info', 'From `logging`.'),
             (name, 'warn', 'From `logging`.'),
@@ -179,6 +181,7 @@
             (name, 'warn', 'From `twisted.logger`.'),
             (name, 'error', 'From `twisted.logger`.'),
             (name, 'info', 'From `twisted.python.log`.'),
+            ('logsomething', 'info', 'From `twisted.python.log.logfile`.'),
             (name, 'info', 'From `logging`.'),
             (name, 'warn', 'From `logging`.'),
             (name, 'error', 'From `logging`.'),
@@ -208,6 +211,7 @@
             (name, 'warn', 'From `twisted.logger`.'),
             (name, 'error', 'From `twisted.logger`.'),
             (name, 'info', 'From `twisted.python.log`.'),
+            ('logsomething', 'info', 'From `twisted.python.log.logfile`.'),
             (name, 'debug', 'From `logging`.'),
             (name, 'info', 'From `logging`.'),
             (name, 'warn', 'From `logging`.'),