Merge lp:~allenap/maas/make-web-access-logs-prettier into lp:~maas-committers/maas/trunk

[Gavin Panella]

Make web access log lines prettier and more readable.

Transforms:

  2017-03-30 23:01:26 regiond: [info] ::ffff:192.168.1.3 - - [30/Mar/2017:22:01:26 +0000] "GET /MAAS/rpc/ HTTP/1.0" 200 208 "-" "provisioningserver.rpc.clusterservice.ClusterClientService"

into:

  2017-03-30 23:01:27 regiond: [info] 192.168.1.3 GET /MAAS/rpc/ HTTP/1.0 --> 200 OK (referrer: -; agent: provisioningserver.rpc.clusterservice.ClusterClientService)

i.e. gets rid of the duplicated timestamp, reorders stuff a bit, and un-IPv6-ifies IPv4 addresses.

[Mike Pontillo (mpontillo)]

I'm on the fence about this one. It looks like our previous logging was /almost/ in the "standard" HTTP log format[1], which has some utility: our current-format might make it easy to analyze the logs with any standard HTTP log analyzer. (ok, granted, maybe after a little grep/sed trickery.)

The best part of this change, to me, is the removal of the IPv4-mapped IPv6 address. That alone makes the log so much better already.

Thoughts?

[1]:
https://en.wikipedia.org/wiki/Common_Log_Format

review: Needs Information

[Gavin Panella (allenap)]

There is utility in the combined log format, which is what Twisted claimed it was producing, but that's reduced because we're publishing it to a "regular" log, where a namespace and level are added, and an additional timestamp. Tools designed for combined logs can't operate on it without pre-processing. In 5 years we haven't shown an interest in analysing this stuff, and there's not much HTTP traffic anyway: the UI is mostly WebSocket traffic and that is not logged. Then, most HTTP traffic is to /MAAS/rpc/ by racks.

To keep access logs for analysis we should pipe them to their own file. t.w.server.Site would prefer to do this: pushing access logs out via the "normal" loggers is a getting-started kind of mode.

But I avoided this because it goes close to the existing can of logging worms (i.e. logging both to regiond.log and journald), because it would need fiddly packaging work (inc. permissions, rotation), and because no one is yet asking for it.

Or, we could override Site.log to publish structured logs from which we can extract, for example, request errors, and produce some kind of in-app report.

In short, here I've tried to optimise for human consumption. We're not shutting the door to other, e.g. machine readable, options later on if we find a need.

[Mike Pontillo (mpontillo)]

Sounds good. +1 from me.

review: Approve

[Gavin Panella (allenap)]

Thanks!

=== modified file 'src/maasserver/tests/test_webapp.py'
--- src/maasserver/tests/test_webapp.py	2017-03-03 17:20:13 +0000
+++ src/maasserver/tests/test_webapp.py	2017-03-30 22:13:21 +0000
@@ -23,6 +23,7 @@
 from maastesting.matchers import MockCalledOnceWith
 from maastesting.testcase import MAASTestCase
 from maastesting.twisted import TwistedLoggerFixture
+from provisioningserver.utils.twisted import reducedWebLogFormatter
 from testtools.matchers import (
     Equals,
     Is,
@@ -205,8 +206,10 @@
     def test__init_creates_site(self):
         service = self.make_webapp()
         self.assertThat(service.site, IsInstance(Site))
-        self.assertThat(
-            service.site.requestFactory, Is(webapp.CleanPathRequest))
+        self.assertThat(service.site, MatchesStructure(
+            requestFactory=Is(webapp.CleanPathRequest),
+            _logFormatter=Is(reducedWebLogFormatter),
+        ))
         self.assertThat(service.websocket, IsInstance(WebSocketFactory))
 
     def test__default_site_renders_starting_page(self):
 
=== modified file 'src/maasserver/webapp.py'
--- src/maasserver/webapp.py	2017-03-03 17:07:03 +0000
+++ src/maasserver/webapp.py	2017-03-30 22:13:21 +0000
@@ -25,6 +25,7 @@
 from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils.twisted import (
     asynchronous,
+    reducedWebLogFormatter,
     ThreadPoolLimiter,
 )
 from twisted.application.internet import StreamServerEndpointService
@@ -184,7 +185,8 @@
     """
 
     def __init__(self, endpoint, listener, status_worker):
-        self.site = OverlaySite(StartPage())
+        self.site = OverlaySite(
+            StartPage(), logFormatter=reducedWebLogFormatter)
         self.site.requestFactory = CleanPathRequest
         super(WebApplicationService, self).__init__(endpoint, self.site)
         self.websocket = WebSocketFactory(listener)
@@ -235,7 +237,8 @@
             WSGIResource(reactor, self.threadpool, application))
         underlay_root = Resource()
         underlay_root.putChild(b'MAAS', underlay_maas)
-        underlay_site = Site(underlay_root)
+        underlay_site = Site(
+            underlay_root, logFormatter=reducedWebLogFormatter)
         underlay_site.requestFactory = CleanPathRequest
 
         # Setup the main resource as the twisted handler and the underlay
 
=== modified file 'src/provisioningserver/rackdservices/image.py'
--- src/provisioningserver/rackdservices/image.py	2015-12-16 14:24:50 +0000
+++ src/provisioningserver/rackdservices/image.py	2017-03-30 22:13:21 +0000
@@ -7,6 +7,7 @@
     "BootImageEndpointService",
     ]
 
+from provisioningserver.utils.twisted import reducedWebLogFormatter
 from twisted.application.internet import StreamServerEndpointService
 from twisted.web.resource import Resource
 from twisted.web.server import Site
@@ -28,5 +29,5 @@
         """
         resource = Resource()
         resource.putChild(b'images', File(resource_root))
-        self.site = Site(resource)
+        self.site = Site(resource, logFormatter=reducedWebLogFormatter)
         super(BootImageEndpointService, self).__init__(endpoint, self.site)
 
=== modified file 'src/provisioningserver/tests/test_plugin.py'
--- src/provisioningserver/tests/test_plugin.py	2017-01-28 00:51:47 +0000
+++ src/provisioningserver/tests/test_plugin.py	2017-03-30 22:13:21 +0000
@@ -46,10 +46,12 @@
 )
 from provisioningserver.rackdservices.tftp_offload import TFTPOffloadService
 from provisioningserver.testing.config import ClusterConfigurationFixture
+from provisioningserver.utils.twisted import reducedWebLogFormatter
 from testtools.matchers import (
     AfterPreprocessing,
     Contains,
     Equals,
+    Is,
     IsInstance,
     KeysEqual,
     MatchesAll,
@@ -206,6 +208,8 @@
         image_service = service.getServiceNamed("image_service")
         self.assertIsInstance(image_service, BootImageEndpointService)
         self.assertIsInstance(image_service.site, Site)
+        self.assertThat(image_service.site, MatchesStructure(
+            _logFormatter=Is(reducedWebLogFormatter)))
         resource = image_service.site.resource
         root = resource.getChildWithDefault(b"images", request=None)
         self.assertThat(root, IsInstance(FilePath))
 
=== modified file 'src/provisioningserver/utils/tests/test_twisted.py'
--- src/provisioningserver/utils/tests/test_twisted.py	2017-03-24 15:28:07 +0000
+++ src/provisioningserver/utils/tests/test_twisted.py	2017-03-30 22:13:21 +0000
@@ -63,6 +63,7 @@
     LONGTIME,
     makeDeferredWithProcessProtocol,
     pause,
+    reducedWebLogFormatter,
     retries,
     RPCFetcher,
     synchronous,
@@ -71,6 +72,7 @@
     ThreadPoolLimiter,
     ThreadUnpool,
 )
+from testscenarios import multiply_scenarios
 from testtools.content import content_from_stream
 from testtools.deferredruntest import assert_fails_with
 from testtools.matchers import (
@@ -88,7 +90,10 @@
     Raises,
 )
 from testtools.testcase import ExpectedException
-from twisted.internet import reactor
+from twisted.internet import (
+    address,
+    reactor,
+)
 from twisted.internet.defer import (
     AlreadyCalledError,
     CancelledError,
@@ -112,6 +117,7 @@
     threadable,
 )
 from twisted.python.failure import Failure
+from twisted.web.test import requesthelper
 
 
 def return_args(*args, **kwargs):
@@ -1883,3 +1889,120 @@
             ))
         self.assertThat(
             twisted_module._os_killpg, MockNotCalled())
+
+
+class TestReducedWebLogFormatter(MAASTestCase):
+    """Tests for `reducedWebLogFormatter`."""
+
+    ipv4_address = factory.make_ipv4_address()
+    ipv6_address = factory.make_ipv6_address()
+    simple_http_url = factory.make_simple_http_url()
+    simple_uri = factory.make_absolute_path()
+    agent_name = factory.make_name("agent")
+    status = factory.make_status_code()
+
+    scenarios_methods = (
+        ("no-method", {"method": None, "method_expected": "???"}),
+        ("method", {"method": "GET", "method_expected": "GET"}),
+    )
+
+    scenarios_clients = (
+        ("no-client", {
+            "client": None,
+            "client_expected": "-",
+        }),
+        ("ipv4-client", {
+            "client": ipv4_address,
+            "client_expected": ipv4_address,
+        }),
+        ("ipv6-client", {
+            "client": ipv6_address,
+            "client_expected": ipv6_address,
+        }),
+        ("ipv4-mapped-client", {
+            "client": "::ffff:" + ipv4_address,
+            "client_expected": ipv4_address,
+        }),
+    )
+
+    scenarios_referrers = (
+        ("no-referrer", {
+            "referrer": None,
+            "referrer_expected": "-",
+        }),
+        ("referrer", {
+            "referrer": simple_http_url,
+            "referrer_expected": simple_http_url,
+        }),
+    )
+
+    scenarios_agents = (
+        ("no-agent", {
+            "agent": None,
+            "agent_expected": "-",
+        }),
+        ("agent", {
+            "agent": agent_name,
+            "agent_expected": agent_name,
+        }),
+    )
+
+    scenarios_uris = (
+        ("no-uri", {
+            "uri": None,
+            "uri_expected": "-",
+        }),
+        ("uri", {
+            "uri": simple_uri,
+            "uri_expected": simple_uri,
+        }),
+    )
+
+    scenarios_statuses = (
+        ("no-status", {
+            "status": None,
+            "status_expected": "???",
+        }),
+        ("status", {
+            "status": status.value,
+            "status_expected": "%d %s" % (status.value, status.name),
+        }),
+        ("status-unknown", {
+            "status": 678,
+            "status_expected": "678",
+        }),
+    )
+
+    scenarios_types = (
+        ("plain", {"prep": lambda string: string}),
+        ("bytes", {"prep": lambda string: (
+            None if string is None else string.encode("ascii"))}),
+    )
+
+    scenarios = multiply_scenarios(
+        scenarios_methods, scenarios_clients, scenarios_referrers,
+        scenarios_agents, scenarios_uris, scenarios_statuses, scenarios_types,
+    )
+
+    def test__renders_full_request(self):
+        request = requesthelper.DummyRequest("foo/bar")
+        request.method = self.prep(self.method)
+        request.client = address.IPv4Address(
+            "TCP", self.prep(self.client), 12345)
+        request.requestHeaders.addRawHeader(
+            "referer", self.prep(self.referrer))
+        request.requestHeaders.addRawHeader(
+            "user-agent", self.prep(self.agent))
+        request.uri = self.prep(self.uri)
+        request.code = self.status
+
+        self.assertThat(
+            reducedWebLogFormatter(sentinel.timestamp, request),
+            Equals(
+                "%s %s %s HTTP/1.0 --> %s (referrer: %s; agent: %s)" % (
+                    self.client_expected, self.method_expected,
+                    self.uri_expected, self.status_expected,
+                    self.referrer_expected, self.agent_expected,
+                )
+            ),
+        )
 
=== modified file 'src/provisioningserver/utils/twisted.py'
--- src/provisioningserver/utils/twisted.py	2017-03-24 15:28:07 +0000
+++ src/provisioningserver/utils/twisted.py	2017-03-30 22:13:21 +0000
@@ -20,6 +20,7 @@
     'LONGTIME',
     'makeDeferredWithProcessProtocol',
     'pause',
+    'reducedWebLogFormatter',
     'retries',
     'synchronous',
     'ThreadPool',
@@ -35,6 +36,7 @@
     partial,
     wraps,
 )
+from http import HTTPStatus
 from itertools import (
     chain,
     repeat,
@@ -50,6 +52,10 @@
 import threading
 
 from crochet import run_in_reactor
+from netaddr import (
+    AddrFormatError,
+    IPAddress,
+)
 from provisioningserver.logger import LegacyLogger
 from twisted.internet import reactor
 from twisted.internet.defer import (
@@ -70,7 +76,9 @@
 )
 from twisted.python.failure import Failure
 from twisted.python.threadable import isInIOThread
+from twisted.web.iweb import IAccessLogFormatter
 from zope import interface
+from zope.interface import provider
 
 
 log = LegacyLogger()
@@ -1043,3 +1051,62 @@
                 killer.cancel()
 
     done.addBoth(callOut, ended)
+
+
+@provider(IAccessLogFormatter)
+def reducedWebLogFormatter(timestamp, request):
+    """Return a reduced formatted log line for the given request.
+
+    The `timestamp` argument is ignored. The line returned is expected to be
+    sent out by a logger which will add its own timestamp, so this one is
+    superfluous.
+
+    :see: `IAccessLogFormatter`
+    :see: `combinedLogFormatter`
+    """
+    template = (
+        "{origin} {method} {uri} {proto} --> {status} "
+        "(referrer: {referrer}; agent: {agent})"
+    )
+
+    def field(value, default):
+        if value is None or len(value) == 0 or value.isspace():
+            return default
+        elif isinstance(value, bytes):
+            return value.decode("ascii", "replace")
+        else:
+            return value
+
+    def normaliseAddress(address):
+        """Normalise an IP address."""
+        try:
+            address = IPAddress(address)
+        except AddrFormatError:
+            return address  # Hostname?
+        else:
+            if address.is_ipv4_mapped():
+                return address.ipv4()
+            else:
+                return address
+
+    def describeHttpStatus(code):
+        try:
+            code = HTTPStatus(code)
+        except ValueError:
+            if isinstance(code, int):
+                return str(code)
+            else:
+                return "???"
+        else:
+            return "{code.value:d} {code.name}".format(code=code)
+
+    origin = field(request.getClientIP(), None)
+    origin = "-" if origin is None else normaliseAddress(origin)
+
+    return template.format(
+        referrer=field(request.getHeader(b"referer"), "-"),
+        agent=field(request.getHeader(b"user-agent"), "-"),
+        status=describeHttpStatus(request.code), origin=origin,
+        method=field(request.method, "???"), uri=field(request.uri, "-"),
+        proto=field(request.clientproto, "-"),
+    )