Introduce new log format markers: i and z

PR #1645 by @spagno:

* ``i`` holds a per-request UUID4
* ``z`` outputs UTC time in format of RFC 3339
* ``cherrypy._cprequest.Request.unique_id.uuid4`` now has lazily
  invocable UUID4

cherrypy/_cplogging.py

@@ -262,6 +262,8 @@ def access(self):
                  'f': dict.get(inheaders, 'Referer', ''),
                  'a': dict.get(inheaders, 'User-Agent', ''),
                  'o': dict.get(inheaders, 'Host', '-'),
+                 'i': request.unique_id,
+                 'z': LazyRfc3339UtcTime(),
                  }
         if six.PY3:
             for k, v in atoms.items():
@@ -462,3 +464,10 @@ def emit(self, record):
                 self.flush()
             except:
                 self.handleError(record)
+
+
+class LazyRfc3339UtcTime(object):
+    def __str__(self):
+        """Return now() in RFC3339 UTC Format."""
+        now = datetime.datetime.now()
+        return now.isoformat('T') + 'Z'

cherrypy/_cprequest.py

@@ -2,6 +2,7 @@
 import time
 import warnings
 
+import uuid
 import six
 from six.moves.http_cookies import SimpleCookie, CookieError
 
@@ -466,6 +467,9 @@ class Request(object):
     A string containing the stage reached in the request-handling process.
     This is useful when debugging a live server with hung requests."""
 
+    unique_id = None
+    """A lazy object generating and memorizing UUID4 on ``str()`` render."""
+
     namespaces = reprconf.NamespaceSet(
         **{'hooks': hooks_namespace,
            'request': request_namespace,
@@ -497,6 +501,8 @@ def __init__(self, local_host, remote_host, scheme='http',
 
         self.stage = None
 
+        self.unique_id = LazyUUID4()
+
     def close(self):
         """Run cleanup code. (Core)"""
         if not self.closed:
@@ -964,3 +970,23 @@ def check_timeout(self):
         """
         if time.time() > self.time + self.timeout:
             self.timed_out = True
+
+
+class LazyUUID4(object):
+    def __str__(self):
+        """Return UUID4 and keep it for future calls."""
+        return str(self.uuid4)
+
+    @property
+    def uuid4(self):
+        """Provide unique id on per-request basis using UUID4.
+
+        It's evaluated lazily on render.
+        """
+        try:
+            self._uuid4
+        except AttributeError:
+            # evaluate on first access
+            self._uuid4 = uuid.uuid4()
+
+        return self._uuid4

cherrypy/test/logtest.py

@@ -2,6 +2,7 @@
 
 import sys
 import time
+from uuid import UUID
 
 import six
 
@@ -161,6 +162,30 @@ def assertNotInLog(self, line, marker=None):
                 msg = '%r found in log' % line
                 self._handleLogError(msg, data, marker, line)
 
+    def assertValidUUIDv4(self, marker=None):
+        """Fail if the given UUIDv4 is not valid.
+
+        The log will be searched from the given marker to the next marker.
+        If marker is None, self.lastmarker is used. If the log hasn't
+        been marked (using self.markLog), the entire log will be searched.
+        """
+        data = self._read_marked_region(marker)
+        data = [chunk.decode('utf-8').rstrip('\n').rstrip('\r') for chunk in data]
+        for log_chunk in data:
+            try:
+                uuid_log = data[-1]
+                uuid_obj = UUID(uuid_log, version=4)
+            except (TypeError, ValueError):
+                pass  # it might be in other chunk
+            else:
+                if str(uuid_obj) == uuid_log:
+                    return
+                msg = '%r is not a valid UUIDv4' % uuid_log
+                self._handleLogError(msg, data, marker, log_chunk)
+
+        msg = 'UUIDv4 not found in log'
+        self._handleLogError(msg, data, marker, log_chunk)
+
     def assertLog(self, sliceargs, lines, marker=None):
         """Fail if log.readlines()[sliceargs] is not contained in 'lines'.
 

cherrypy/test/test_logging.py

@@ -1,6 +1,7 @@
 """Basic tests for the CherryPy core: request handling."""
 
 import os
+from unittest import mock
 
 import six
 
@@ -106,17 +107,14 @@ def testNormalYield(self):
             self.assertLog(-1, '] "GET %s/as_yield HTTP/1.1" 200 - "" ""'
                            % self.prefix())
 
+    @mock.patch(
+        'cherrypy._cplogging.LogManager.access_log_format',
+        '{h} {l} {u} {t} "{r}" {s} {b} "{f}" "{a}" {o}'
+        if six.PY3 else
+        '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %(o)s'
+    )
     def testCustomLogFormat(self):
-        '''Test a customized access_log_format string,
-           which is a feature of _cplogging.LogManager.access() '''
-
-        original_logformat = cherrypy._cplogging.LogManager.access_log_format
-        cherrypy._cplogging.LogManager.access_log_format = (
-            '{h} {l} {u} {t} "{r}" {s} {b} "{f}" "{a}" {o}' if six.PY3
-            else
-            '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %(o)s'
-        )
-
+        """Test a customized access_log_format string, which is a feature of _cplogging.LogManager.access()."""
         self.markLog()
         self.getPage('/as_string', headers=[('Referer', 'REFERER'),
                                             ('User-Agent', 'USERAGENT'),
@@ -125,7 +123,36 @@ def testCustomLogFormat(self):
         self.assertLog(-1, '] "GET /as_string HTTP/1.1" '
                            '200 7 "REFERER" "USERAGENT" HOST')
 
-        cherrypy._cplogging.LogManager.access_log_format = original_logformat
+    @mock.patch(
+        'cherrypy._cplogging.LogManager.access_log_format',
+        '{h} {l} {u} {z} "{r}" {s} {b} "{f}" "{a}" {o}'
+        if six.PY3 else
+        '%(h)s %(l)s %(u)s %(z)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %(o)s'
+    )
+    def testTimezLogFormat(self):
+        """Test a customized access_log_format string, which is a feature of _cplogging.LogManager.access()."""
+        self.markLog()
+
+        expected_time = str(cherrypy._cplogging.LazyRfc3339UtcTime())
+        with mock.patch('cherrypy._cplogging.LazyRfc3339UtcTime', lambda: expected_time):
+            self.getPage('/as_string', headers=[('Referer', 'REFERER'),
+                                                ('User-Agent', 'USERAGENT'),
+                                                ('Host', 'HOST')])
+
+        self.assertLog(-1, '%s - - ' % self.interface())
+        self.assertLog(-1, expected_time)
+        self.assertLog(-1, ' "GET /as_string HTTP/1.1" '
+                           '200 7 "REFERER" "USERAGENT" HOST')
+
+    @mock.patch(
+        'cherrypy._cplogging.LogManager.access_log_format',
+        '{i}' if six.PY3 else '%(i)s'
+    )
+    def testUUIDv4ParameterLogFormat(self):
+        """Test rendering of UUID4 within access log."""
+        self.markLog()
+        self.getPage('/as_string')
+        self.assertValidUUIDv4()
 
     def testEscapedOutput(self):
         # Test unicode in access log pieces.

cherrypy/test/test_request_obj.py

@@ -4,6 +4,7 @@
 import os
 import sys
 import types
+import uuid
 
 import six
 from six.moves.http_client import IncompleteRead
@@ -46,6 +47,14 @@ def body_example_com_3128(self):
                 """Handle CONNECT method."""
                 return cherrypy.request.method + 'ed to ' + cherrypy.request.path_info
 
+            @cherrypy.expose
+            def request_uuid4(self):
+                return [
+                    str(cherrypy.request.unique_id),
+                    ' ',
+                    str(cherrypy.request.unique_id),
+                ]
+
         root = Root()
 
         class TestType(type):
@@ -311,6 +320,15 @@ def test_scheme(self):
         self.getPage('/scheme')
         self.assertBody(self.scheme)
 
+    def test_per_request_uuid4(self):
+        self.getPage('/request_uuid4')
+        first_uuid4, _, second_uuid4 = self.body.decode().partition(' ')
+        assert uuid.UUID(first_uuid4, version=4) == uuid.UUID(second_uuid4, version=4)
+
+        self.getPage('/request_uuid4')
+        third_uuid4, _, _ = self.body.decode().partition(' ')
+        assert uuid.UUID(first_uuid4, version=4) != uuid.UUID(third_uuid4, version=4)
+
     def testRelativeURIPathInfo(self):
         self.getPage('/pathinfo/foo/bar')
         self.assertBody('/pathinfo/foo/bar')