From 5d953c0117f9236728308912383bdbb0db6097a9 Mon Sep 17 00:00:00 2001 From: spagno Date: Tue, 17 Oct 2017 18:37:47 +0200 Subject: [PATCH 01/44] Added uuidv4 and now() in RFC3339 UTC Format --- cherrypy/_cplogging.py | 15 +++++++++++---- 1 file changed, 11 insertions(+), 4 deletions(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 79fe5a8d5..40c42657e 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -111,14 +111,13 @@ import logging import os import sys - -import six +import uuid import cherrypy +import six from cherrypy import _cperror from cherrypy._cpcompat import ntob - # Silence the no-handlers "warning" (stderr write!) in stdlib logging logging.Logger.manager.emittedNoHandlerWarning = 1 logfmt = logging.Formatter('%(message)s') @@ -216,7 +215,8 @@ def error(self, msg='', context='', severity=logging.INFO, if traceback: exc_info = _cperror._exc_info() - self.error_log.log(severity, ' '.join((self.time(), context, msg)), exc_info=exc_info) + self.error_log.log(severity, ' '.join( + (self.time(), context, msg)), exc_info=exc_info) def __call__(self, *args, **kwargs): """An alias for ``error``.""" @@ -262,6 +262,8 @@ def access(self): 'f': dict.get(inheaders, 'Referer', ''), 'a': dict.get(inheaders, 'User-Agent', ''), 'o': dict.get(inheaders, 'Host', '-'), + '4': uuid.uuid4(), + 'z': self.time_z(), } if six.PY3: for k, v in atoms.items(): @@ -312,6 +314,11 @@ def time(self): return ('[%02d/%s/%04d:%02d:%02d:%02d]' % (now.day, month, now.year, now.hour, now.minute, now.second)) + def time_z(self): + """Return now() in RFC3339 UTC Format.""" + now = datetime.datetime.now() + return now.isoformat("T") + "Z" + def _get_builtin_handler(self, log, key): for h in log.handlers: if getattr(h, '_cpbuiltin', None) == key: From c88e931275e9760e9945043202f057daee76ed12 Mon Sep 17 00:00:00 2001 From: spagno Date: Tue, 17 Oct 2017 20:24:18 +0200 Subject: [PATCH 02/44] Fix double quoted strings - fixed --- cherrypy/_cplogging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 40c42657e..632dbe478 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -317,7 +317,7 @@ def time(self): def time_z(self): """Return now() in RFC3339 UTC Format.""" now = datetime.datetime.now() - return now.isoformat("T") + "Z" + return now.isoformat('T') + 'Z' def _get_builtin_handler(self, log, key): for h in log.handlers: From dbb0a40b3b051c690ffc6b95c240dd5cdebd4b0c Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 02:13:13 +0200 Subject: [PATCH 03/44] Fix atoms char --- cherrypy/_cplogging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 632dbe478..3259428c9 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -262,7 +262,7 @@ def access(self): 'f': dict.get(inheaders, 'Referer', ''), 'a': dict.get(inheaders, 'User-Agent', ''), 'o': dict.get(inheaders, 'Host', '-'), - '4': uuid.uuid4(), + 'i': str(uuid.uuid4()), 'z': self.time_z(), } if six.PY3: From 4cbab320067805230f315c56dbadbc389f9134de Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 03:34:36 +0200 Subject: [PATCH 04/44] Added tests --- cherrypy/test/logtest.py | 25 ++++++++++++++++++++++- cherrypy/test/test_logging.py | 38 +++++++++++++++++++++++++++++++++++ 2 files changed, 62 insertions(+), 1 deletion(-) diff --git a/cherrypy/test/logtest.py b/cherrypy/test/logtest.py index 5361cfb88..d18493ccd 100644 --- a/cherrypy/test/logtest.py +++ b/cherrypy/test/logtest.py @@ -4,7 +4,7 @@ import time import six - +from uuid import UUID from cherrypy._cpcompat import text_or_bytes, ntob @@ -161,6 +161,29 @@ 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) + uuid_obj = '' + msg = '' + for lines in data: + uuid_log = lines[:-1].decode("utf-8") + uuid_obj = UUID(uuid_log, version=4) + try: + uuid_obj = UUID(uuid_log, version=4) + except: + msg = '%r not a valid UUIDv4' % uuid_log + finally: + if str(uuid_obj) != uuid_log: + msg = '%r not a valid UUIDv4' % uuid_log + self._handleLogError(msg, data, marker, lines) + + def assertLog(self, sliceargs, lines, marker=None): """Fail if log.readlines()[sliceargs] is not contained in 'lines'. diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index 4f23f8857..1549f7bda 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -127,6 +127,44 @@ def testCustomLogFormat(self): cherrypy._cplogging.LogManager.access_log_format = original_logformat + def testUUIDv4ParameterLogFormat(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 = ( + '{i}' if six.PY3 + else + '%(i)s' + ) + + self.markLog() + self.getPage('/as_string') + self.assertValidUUIDv4() + + cherrypy._cplogging.LogManager.access_log_format = original_logformat + + def testTimezLogFormat(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} {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' + ) + + self.markLog() + self.getPage('/as_string', headers=[('Referer', 'REFERER'), + ('User-Agent', 'USERAGENT'), + ('Host', 'HOST')]) + self.assertLog(-1, '%s - - ' % self.interface()) + self.assertLog(-1, ' "GET /as_string HTTP/1.1" ' + '200 7 "REFERER" "USERAGENT" HOST') + + cherrypy._cplogging.LogManager.access_log_format = original_logformat + def testEscapedOutput(self): # Test unicode in access log pieces. self.markLog() From bb96f61982bad5d9d0d7142c4e01428b5a6dfec3 Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 03:40:18 +0200 Subject: [PATCH 05/44] Fixed Flake8 --- cherrypy/test/logtest.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/cherrypy/test/logtest.py b/cherrypy/test/logtest.py index d18493ccd..3e30a1b8f 100644 --- a/cherrypy/test/logtest.py +++ b/cherrypy/test/logtest.py @@ -172,7 +172,7 @@ def assertValidUUIDv4(self, marker=None): uuid_obj = '' msg = '' for lines in data: - uuid_log = lines[:-1].decode("utf-8") + uuid_log = lines[:-1].decode('utf-8') uuid_obj = UUID(uuid_log, version=4) try: uuid_obj = UUID(uuid_log, version=4) @@ -183,7 +183,6 @@ def assertValidUUIDv4(self, marker=None): msg = '%r not a valid UUIDv4' % uuid_log self._handleLogError(msg, data, marker, lines) - def assertLog(self, sliceargs, lines, marker=None): """Fail if log.readlines()[sliceargs] is not contained in 'lines'. From 3680a2ad076f3f147d0d7379be7d86ffd40a5d7e Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 03:44:51 +0200 Subject: [PATCH 06/44] Fixed UUIDv4 test --- cherrypy/test/logtest.py | 1 - 1 file changed, 1 deletion(-) diff --git a/cherrypy/test/logtest.py b/cherrypy/test/logtest.py index 3e30a1b8f..40d204235 100644 --- a/cherrypy/test/logtest.py +++ b/cherrypy/test/logtest.py @@ -173,7 +173,6 @@ def assertValidUUIDv4(self, marker=None): msg = '' for lines in data: uuid_log = lines[:-1].decode('utf-8') - uuid_obj = UUID(uuid_log, version=4) try: uuid_obj = UUID(uuid_log, version=4) except: From 7d48070003cb57ff5d9fa236dbb638fa314354c3 Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 04:12:30 +0200 Subject: [PATCH 07/44] Removed bad implemented tests --- cherrypy/test/logtest.py | 22 -------------------- cherrypy/test/test_logging.py | 38 ----------------------------------- 2 files changed, 60 deletions(-) diff --git a/cherrypy/test/logtest.py b/cherrypy/test/logtest.py index 40d204235..0d76a9eb6 100644 --- a/cherrypy/test/logtest.py +++ b/cherrypy/test/logtest.py @@ -4,7 +4,6 @@ import time import six -from uuid import UUID from cherrypy._cpcompat import text_or_bytes, ntob @@ -161,27 +160,6 @@ 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) - uuid_obj = '' - msg = '' - for lines in data: - uuid_log = lines[:-1].decode('utf-8') - try: - uuid_obj = UUID(uuid_log, version=4) - except: - msg = '%r not a valid UUIDv4' % uuid_log - finally: - if str(uuid_obj) != uuid_log: - msg = '%r not a valid UUIDv4' % uuid_log - self._handleLogError(msg, data, marker, lines) - def assertLog(self, sliceargs, lines, marker=None): """Fail if log.readlines()[sliceargs] is not contained in 'lines'. diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index 1549f7bda..4f23f8857 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -127,44 +127,6 @@ def testCustomLogFormat(self): cherrypy._cplogging.LogManager.access_log_format = original_logformat - def testUUIDv4ParameterLogFormat(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 = ( - '{i}' if six.PY3 - else - '%(i)s' - ) - - self.markLog() - self.getPage('/as_string') - self.assertValidUUIDv4() - - cherrypy._cplogging.LogManager.access_log_format = original_logformat - - def testTimezLogFormat(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} {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' - ) - - self.markLog() - self.getPage('/as_string', headers=[('Referer', 'REFERER'), - ('User-Agent', 'USERAGENT'), - ('Host', 'HOST')]) - self.assertLog(-1, '%s - - ' % self.interface()) - self.assertLog(-1, ' "GET /as_string HTTP/1.1" ' - '200 7 "REFERER" "USERAGENT" HOST') - - cherrypy._cplogging.LogManager.access_log_format = original_logformat - def testEscapedOutput(self): # Test unicode in access log pieces. self.markLog() From 122fd0506d30152a026ca0a0e56b5eda630773b3 Mon Sep 17 00:00:00 2001 From: Andrea Spagnolo Date: Wed, 18 Oct 2017 12:58:58 +0200 Subject: [PATCH 08/44] Fixed test on windows --- cherrypy/_cplogging.py | 7 ++++--- cherrypy/test/logtest.py | 22 ++++++++++++++++++++++ 2 files changed, 26 insertions(+), 3 deletions(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 3259428c9..7cb638f21 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -111,10 +111,12 @@ import logging import os import sys + +import six import uuid import cherrypy -import six + from cherrypy import _cperror from cherrypy._cpcompat import ntob @@ -215,8 +217,7 @@ def error(self, msg='', context='', severity=logging.INFO, if traceback: exc_info = _cperror._exc_info() - self.error_log.log(severity, ' '.join( - (self.time(), context, msg)), exc_info=exc_info) + self.error_log.log(severity, ' '.join((self.time(), context, msg)), exc_info=exc_info) def __call__(self, *args, **kwargs): """An alias for ``error``.""" diff --git a/cherrypy/test/logtest.py b/cherrypy/test/logtest.py index 0d76a9eb6..ba510f2d5 100644 --- a/cherrypy/test/logtest.py +++ b/cherrypy/test/logtest.py @@ -4,6 +4,7 @@ import time import six + from cherrypy._cpcompat import text_or_bytes, ntob @@ -160,6 +161,27 @@ 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): + msg = '%r not a valid UUIDv4' % uuid_log + self._handleLogError(msg, data, marker, lines) + else: + if str(uuid_obj) != uuid_log: + msg = '%r not a valid UUIDv4' % uuid_log + self._handleLogError(msg, data, marker, lines) + def assertLog(self, sliceargs, lines, marker=None): """Fail if log.readlines()[sliceargs] is not contained in 'lines'. From 3497a8223d2a84f3fb62f4448b1c88a00b73b299 Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 16:18:08 +0200 Subject: [PATCH 09/44] Fixed typo --- cherrypy/test/logtest.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/cherrypy/test/logtest.py b/cherrypy/test/logtest.py index ba510f2d5..ef34f9ff9 100644 --- a/cherrypy/test/logtest.py +++ b/cherrypy/test/logtest.py @@ -176,11 +176,11 @@ def assertValidUUIDv4(self, marker=None): uuid_obj = UUID(uuid_log, version=4) except (TypeError, ValueError): msg = '%r not a valid UUIDv4' % uuid_log - self._handleLogError(msg, data, marker, lines) + self._handleLogError(msg, data, marker, log_chunk) else: if str(uuid_obj) != uuid_log: msg = '%r not a valid UUIDv4' % uuid_log - self._handleLogError(msg, data, marker, lines) + self._handleLogError(msg, data, marker, log_chunk) def assertLog(self, sliceargs, lines, marker=None): """Fail if log.readlines()[sliceargs] is not contained in 'lines'. From 38a0a739e55546b83850d06e878ebcb2a1537221 Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 16:20:50 +0200 Subject: [PATCH 10/44] Added tests in test_logging.py --- cherrypy/test/test_logging.py | 38 +++++++++++++++++++++++++++++++++++ 1 file changed, 38 insertions(+) diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index 4f23f8857..1549f7bda 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -127,6 +127,44 @@ def testCustomLogFormat(self): cherrypy._cplogging.LogManager.access_log_format = original_logformat + def testUUIDv4ParameterLogFormat(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 = ( + '{i}' if six.PY3 + else + '%(i)s' + ) + + self.markLog() + self.getPage('/as_string') + self.assertValidUUIDv4() + + cherrypy._cplogging.LogManager.access_log_format = original_logformat + + def testTimezLogFormat(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} {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' + ) + + self.markLog() + self.getPage('/as_string', headers=[('Referer', 'REFERER'), + ('User-Agent', 'USERAGENT'), + ('Host', 'HOST')]) + self.assertLog(-1, '%s - - ' % self.interface()) + self.assertLog(-1, ' "GET /as_string HTTP/1.1" ' + '200 7 "REFERER" "USERAGENT" HOST') + + cherrypy._cplogging.LogManager.access_log_format = original_logformat + def testEscapedOutput(self): # Test unicode in access log pieces. self.markLog() From bde1cb5b96405d11965b8f89ae5d3cb6f9a52097 Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 16:20:50 +0200 Subject: [PATCH 11/44] Added tests in test_logging.py --- cherrypy/test/test_logging.py | 38 +++++++++++++++++++++++++++++++++++ 1 file changed, 38 insertions(+) diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index 1549f7bda..99ae6b242 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -165,6 +165,44 @@ def testTimezLogFormat(self): cherrypy._cplogging.LogManager.access_log_format = original_logformat + def testUUIDv4ParameterLogFormat(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 = ( + '{i}' if six.PY3 + else + '%(i)s' + ) + + self.markLog() + self.getPage('/as_string') + self.assertValidUUIDv4() + + cherrypy._cplogging.LogManager.access_log_format = original_logformat + + def testTimezLogFormat(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} {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' + ) + + self.markLog() + self.getPage('/as_string', headers=[('Referer', 'REFERER'), + ('User-Agent', 'USERAGENT'), + ('Host', 'HOST')]) + self.assertLog(-1, '%s - - ' % self.interface()) + self.assertLog(-1, ' "GET /as_string HTTP/1.1" ' + '200 7 "REFERER" "USERAGENT" HOST') + + cherrypy._cplogging.LogManager.access_log_format = original_logformat + def testEscapedOutput(self): # Test unicode in access log pieces. self.markLog() From a0bb360eb8d1ded9c78374151eeb96f490604933 Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 16:45:20 +0200 Subject: [PATCH 12/44] Now time_z is a staticmethod --- cherrypy/_cplogging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 7cb638f21..d7fc177f8 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -314,7 +314,7 @@ def time(self): month = monthnames[now.month - 1].capitalize() return ('[%02d/%s/%04d:%02d:%02d:%02d]' % (now.day, month, now.year, now.hour, now.minute, now.second)) - + @staticmethod def time_z(self): """Return now() in RFC3339 UTC Format.""" now = datetime.datetime.now() From a2c860517be89bb48ed655cd1c26b136936d4598 Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 16:55:44 +0200 Subject: [PATCH 13/44] Added newline --- cherrypy/_cplogging.py | 1 + 1 file changed, 1 insertion(+) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index d7fc177f8..43e9702ea 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -314,6 +314,7 @@ def time(self): month = monthnames[now.month - 1].capitalize() return ('[%02d/%s/%04d:%02d:%02d:%02d]' % (now.day, month, now.year, now.hour, now.minute, now.second)) + @staticmethod def time_z(self): """Return now() in RFC3339 UTC Format.""" From 011f5c2f50293f4b6ca312716d4352645331d3cd Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 16:58:01 +0200 Subject: [PATCH 14/44] Fixed staticmethod --- cherrypy/_cplogging.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 43e9702ea..a76c52f79 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -314,9 +314,9 @@ def time(self): month = monthnames[now.month - 1].capitalize() return ('[%02d/%s/%04d:%02d:%02d:%02d]' % (now.day, month, now.year, now.hour, now.minute, now.second)) - + @staticmethod - def time_z(self): + def time_z(): """Return now() in RFC3339 UTC Format.""" now = datetime.datetime.now() return now.isoformat('T') + 'Z' From cb21f416e39028709c8723f80462e950486d33b7 Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 17:16:33 +0200 Subject: [PATCH 15/44] Removed unnecessary newline --- cherrypy/_cplogging.py | 1 - 1 file changed, 1 deletion(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index a76c52f79..257f63626 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -116,7 +116,6 @@ import uuid import cherrypy - from cherrypy import _cperror from cherrypy._cpcompat import ntob From 7842d2efb093592de522173452e80e75473a0083 Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 17:22:16 +0200 Subject: [PATCH 16/44] pep257 docstring compliant --- cherrypy/test/test_logging.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index 99ae6b242..4999c4fcf 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -107,8 +107,8 @@ def testNormalYield(self): % self.prefix()) def testCustomLogFormat(self): - '''Test a customized access_log_format string, - which is a feature of _cplogging.LogManager.access() ''' + """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 = ( @@ -128,8 +128,8 @@ def testCustomLogFormat(self): cherrypy._cplogging.LogManager.access_log_format = original_logformat def testUUIDv4ParameterLogFormat(self): - '''Test a customized access_log_format string, - which is a feature of _cplogging.LogManager.access() ''' + """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 = ( @@ -145,8 +145,8 @@ def testUUIDv4ParameterLogFormat(self): cherrypy._cplogging.LogManager.access_log_format = original_logformat def testTimezLogFormat(self): - '''Test a customized access_log_format string, - which is a feature of _cplogging.LogManager.access() ''' + """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 = ( From 0a07fcb9002a00309c9a8951d53d2a6cb01f3be4 Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 17:27:19 +0200 Subject: [PATCH 17/44] Restored newline --- cherrypy/_cplogging.py | 1 + 1 file changed, 1 insertion(+) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 257f63626..e552bd7c0 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -119,6 +119,7 @@ from cherrypy import _cperror from cherrypy._cpcompat import ntob + # Silence the no-handlers "warning" (stderr write!) in stdlib logging logging.Logger.manager.emittedNoHandlerWarning = 1 logfmt = logging.Formatter('%(message)s') From 0c9eefb3435ab390df3faca3b046a9687e48bf3b Mon Sep 17 00:00:00 2001 From: spagno Date: Wed, 18 Oct 2017 17:35:44 +0200 Subject: [PATCH 18/44] PEP257 Docstring fixed --- cherrypy/test/test_logging.py | 12 +++--------- 1 file changed, 3 insertions(+), 9 deletions(-) diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index 4999c4fcf..b43d726a1 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -107,9 +107,7 @@ def testNormalYield(self): % self.prefix()) def testCustomLogFormat(self): - """Test a customized access_log_format string, - which is a feature of _cplogging.LogManager.access() """ - + """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 @@ -128,9 +126,7 @@ def testCustomLogFormat(self): cherrypy._cplogging.LogManager.access_log_format = original_logformat def testUUIDv4ParameterLogFormat(self): - """Test a customized access_log_format string, - which is a feature of _cplogging.LogManager.access() """ - + """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 = ( '{i}' if six.PY3 @@ -145,9 +141,7 @@ def testUUIDv4ParameterLogFormat(self): cherrypy._cplogging.LogManager.access_log_format = original_logformat def testTimezLogFormat(self): - """Test a customized access_log_format string, - which is a feature of _cplogging.LogManager.access() """ - + """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} {z} "{r}" {s} {b} "{f}" "{a}" {o}' if six.PY3 From 67c6901868c88f8750a76d10760c5d85ae0c1d6c Mon Sep 17 00:00:00 2001 From: spagno Date: Thu, 19 Oct 2017 18:50:29 +0200 Subject: [PATCH 19/44] New uuid calc --- cherrypy/_cplogging.py | 4 +--- cherrypy/_cprequest.py | 5 +++++ 2 files changed, 6 insertions(+), 3 deletions(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index e552bd7c0..6164f1a6e 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -113,7 +113,6 @@ import sys import six -import uuid import cherrypy from cherrypy import _cperror @@ -252,7 +251,6 @@ def access(self): status = response.output_status.split(ntob(' '), 1)[0] if six.PY3: status = status.decode('ISO-8859-1') - atoms = {'h': remote.name or remote.ip, 'l': '-', 'u': getattr(request, 'login', None) or '-', @@ -263,7 +261,7 @@ def access(self): 'f': dict.get(inheaders, 'Referer', ''), 'a': dict.get(inheaders, 'User-Agent', ''), 'o': dict.get(inheaders, 'Host', '-'), - 'i': str(uuid.uuid4()), + 'i': response.uuid, 'z': self.time_z(), } if six.PY3: diff --git a/cherrypy/_cprequest.py b/cherrypy/_cprequest.py index 71f867fd8..7634661a2 100644 --- a/cherrypy/_cprequest.py +++ b/cherrypy/_cprequest.py @@ -4,6 +4,7 @@ import six from six.moves.http_cookies import SimpleCookie, CookieError +import uuid import cherrypy from cherrypy._cpcompat import text_or_bytes, ntob @@ -911,6 +912,9 @@ def collapse_body(self): self.body = newbody return newbody + def __str__(self): + return uuid.uuid4() + def finalize(self): """Transform headers (and cookies) into self.header_list. (Core)""" try: @@ -923,6 +927,7 @@ def finalize(self): self.status = '%s %s' % (code, reason) self.output_status = ntob(str(code), 'ascii') + \ ntob(' ') + headers.encode(reason) + self.uuid = self.__str__() if self.stream: # The upshot: wsgiserver will chunk the response if From b42a1e9d00d85ed420846a4b09e7de544e3b519f Mon Sep 17 00:00:00 2001 From: spagno Date: Thu, 19 Oct 2017 18:55:46 +0200 Subject: [PATCH 20/44] fixed newline --- cherrypy/_cplogging.py | 1 + 1 file changed, 1 insertion(+) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 6164f1a6e..18fd78ac2 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -251,6 +251,7 @@ def access(self): status = response.output_status.split(ntob(' '), 1)[0] if six.PY3: status = status.decode('ISO-8859-1') + atoms = {'h': remote.name or remote.ip, 'l': '-', 'u': getattr(request, 'login', None) or '-', From 1a8fd6a8e362b6c9be17912232d172738e31d865 Mon Sep 17 00:00:00 2001 From: spagno Date: Thu, 19 Oct 2017 18:56:28 +0200 Subject: [PATCH 21/44] fixed unnecessary spaces --- cherrypy/_cplogging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 18fd78ac2..3a4a17382 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -251,7 +251,7 @@ def access(self): status = response.output_status.split(ntob(' '), 1)[0] if six.PY3: status = status.decode('ISO-8859-1') - + atoms = {'h': remote.name or remote.ip, 'l': '-', 'u': getattr(request, 'login', None) or '-', From 565c730d3f530c810d1b55afaba702defc363b97 Mon Sep 17 00:00:00 2001 From: spagno Date: Thu, 19 Oct 2017 20:12:45 +0200 Subject: [PATCH 22/44] uuid lazy property --- cherrypy/_cplogging.py | 40 +++++++++++++++++++++++++++++++++++++++- cherrypy/_cprequest.py | 5 ----- 2 files changed, 39 insertions(+), 6 deletions(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 3a4a17382..72eaa244e 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -113,6 +113,7 @@ import sys import six +import uuid import cherrypy from cherrypy import _cperror @@ -138,6 +139,39 @@ def createLock(self): self.lock = None +class CachedUuid(object): + def __init__(self, wrapped): + self.wrapped = wrapped + try: + self.__doc__ = wrapped.__doc__ + except: # pragma: no cover + pass + + # original sets the attributes on the instance + # def __get__(self, inst, objtype=None): + # if inst is None: + # return self + # val = self.wrapped(inst) + # setattr(inst, self.wrapped.__name__, val) + # return val + + # ignore the instance, and just set them on the class + # if called on a class, inst is None and objtype is the class + # if called on an instance, inst is the instance, and objtype + # the class + def __get__(self, inst, objtype=None): + # ask the value from the wrapped object, giving it + # our class + val = self.wrapped(objtype) + + # and set the attribute directly to the class, thereby + # avoiding the descriptor to be called multiple times + setattr(objtype, self.wrapped.__name__, val) + + # and return the calculated value + return val + + class LogManager(object): """An object to assist both simple and advanced logging. @@ -262,7 +296,7 @@ def access(self): 'f': dict.get(inheaders, 'Referer', ''), 'a': dict.get(inheaders, 'User-Agent', ''), 'o': dict.get(inheaders, 'Host', '-'), - 'i': response.uuid, + 'i': self.get_uuid(), 'z': self.time_z(), } if six.PY3: @@ -319,6 +353,10 @@ def time_z(): """Return now() in RFC3339 UTC Format.""" now = datetime.datetime.now() return now.isoformat('T') + 'Z' + + @CachedUuid + def get_uuid(cls): + return uuid.uuid4() def _get_builtin_handler(self, log, key): for h in log.handlers: diff --git a/cherrypy/_cprequest.py b/cherrypy/_cprequest.py index 7634661a2..71f867fd8 100644 --- a/cherrypy/_cprequest.py +++ b/cherrypy/_cprequest.py @@ -4,7 +4,6 @@ import six from six.moves.http_cookies import SimpleCookie, CookieError -import uuid import cherrypy from cherrypy._cpcompat import text_or_bytes, ntob @@ -912,9 +911,6 @@ def collapse_body(self): self.body = newbody return newbody - def __str__(self): - return uuid.uuid4() - def finalize(self): """Transform headers (and cookies) into self.header_list. (Core)""" try: @@ -927,7 +923,6 @@ def finalize(self): self.status = '%s %s' % (code, reason) self.output_status = ntob(str(code), 'ascii') + \ ntob(' ') + headers.encode(reason) - self.uuid = self.__str__() if self.stream: # The upshot: wsgiserver will chunk the response if From 65656dfd1eba9f6521d5254af32cf4782d7c4d65 Mon Sep 17 00:00:00 2001 From: spagno Date: Thu, 19 Oct 2017 20:23:31 +0200 Subject: [PATCH 23/44] Trying new method --- cherrypy/_cplogging.py | 47 +++++++++--------------------------------- 1 file changed, 10 insertions(+), 37 deletions(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 72eaa244e..10b1a5dcd 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -138,39 +138,15 @@ def emit(self, record): def createLock(self): self.lock = None +class GetUuid(object): + def __init__(self): + self._uuid = None -class CachedUuid(object): - def __init__(self, wrapped): - self.wrapped = wrapped - try: - self.__doc__ = wrapped.__doc__ - except: # pragma: no cover - pass - - # original sets the attributes on the instance - # def __get__(self, inst, objtype=None): - # if inst is None: - # return self - # val = self.wrapped(inst) - # setattr(inst, self.wrapped.__name__, val) - # return val - - # ignore the instance, and just set them on the class - # if called on a class, inst is None and objtype is the class - # if called on an instance, inst is the instance, and objtype - # the class - def __get__(self, inst, objtype=None): - # ask the value from the wrapped object, giving it - # our class - val = self.wrapped(objtype) - - # and set the attribute directly to the class, thereby - # avoiding the descriptor to be called multiple times - setattr(objtype, self.wrapped.__name__, val) - - # and return the calculated value - return val - + @property + def get_uuid(self): + if self._uuid is None: + self._uuid = uuid.uuid4() + return self._uuid class LogManager(object): @@ -279,6 +255,7 @@ def access(self): response = cherrypy.serving.response outheaders = response.headers inheaders = request.headers + request_uid = GetUuid() if response.output_status is None: status = '-' else: @@ -296,7 +273,7 @@ def access(self): 'f': dict.get(inheaders, 'Referer', ''), 'a': dict.get(inheaders, 'User-Agent', ''), 'o': dict.get(inheaders, 'Host', '-'), - 'i': self.get_uuid(), + 'i': request_uid.get_uuid(), 'z': self.time_z(), } if six.PY3: @@ -353,10 +330,6 @@ def time_z(): """Return now() in RFC3339 UTC Format.""" now = datetime.datetime.now() return now.isoformat('T') + 'Z' - - @CachedUuid - def get_uuid(cls): - return uuid.uuid4() def _get_builtin_handler(self, log, key): for h in log.handlers: From cb9cd8fbd87864336d1af776aac41e6268bf4f48 Mon Sep 17 00:00:00 2001 From: spagno Date: Thu, 19 Oct 2017 20:24:56 +0200 Subject: [PATCH 24/44] Added required blankline --- cherrypy/_cplogging.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 10b1a5dcd..8b44c21fd 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -138,6 +138,7 @@ def emit(self, record): def createLock(self): self.lock = None + class GetUuid(object): def __init__(self): self._uuid = None @@ -148,6 +149,7 @@ def get_uuid(self): self._uuid = uuid.uuid4() return self._uuid + class LogManager(object): """An object to assist both simple and advanced logging. From 14a0af80d4360ba979292592c7a871b2eb081092 Mon Sep 17 00:00:00 2001 From: spagno Date: Thu, 19 Oct 2017 23:02:46 +0200 Subject: [PATCH 25/44] Fixed uuidv4 generation --- cherrypy/_cplogging.py | 15 +-------------- cherrypy/_cprequest.py | 22 ++++++++++++++++++++++ 2 files changed, 23 insertions(+), 14 deletions(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 8b44c21fd..a40f9855f 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -113,7 +113,6 @@ import sys import six -import uuid import cherrypy from cherrypy import _cperror @@ -139,17 +138,6 @@ def createLock(self): self.lock = None -class GetUuid(object): - def __init__(self): - self._uuid = None - - @property - def get_uuid(self): - if self._uuid is None: - self._uuid = uuid.uuid4() - return self._uuid - - class LogManager(object): """An object to assist both simple and advanced logging. @@ -257,7 +245,6 @@ def access(self): response = cherrypy.serving.response outheaders = response.headers inheaders = request.headers - request_uid = GetUuid() if response.output_status is None: status = '-' else: @@ -275,7 +262,7 @@ def access(self): 'f': dict.get(inheaders, 'Referer', ''), 'a': dict.get(inheaders, 'User-Agent', ''), 'o': dict.get(inheaders, 'Host', '-'), - 'i': request_uid.get_uuid(), + 'i': request.uuid, 'z': self.time_z(), } if six.PY3: diff --git a/cherrypy/_cprequest.py b/cherrypy/_cprequest.py index 71f867fd8..e3459bee4 100644 --- a/cherrypy/_cprequest.py +++ b/cherrypy/_cprequest.py @@ -2,6 +2,7 @@ import time import warnings +import uuid import six from six.moves.http_cookies import SimpleCookie, CookieError @@ -834,6 +835,20 @@ def __set__(self, obj, value): obj._body = value +class RequestUuid(object): + + """The UUIDv4.""" + def __get__(self, obj, objclass=None): + if obj is None: + # When calling on the class instead of instance... + return self + else: + return obj._uuid + + def __set__(self, obj, value): + obj._uuid = uuid.uuid4() + + class Response(object): """An HTTP Response, including status, headers, and body.""" @@ -879,11 +894,15 @@ class Response(object): stream = False """If False, buffer the response body.""" + uuid = RequestUuid() + """The uuidv4 (entity) of the HTTP request.""" + def __init__(self): self.status = None self.header_list = None self._body = [] self.time = time.time() + self._uuid = None self.headers = httputil.HeaderMap() # Since we know all our keys are titled strings, we can @@ -895,6 +914,9 @@ def __init__(self): }) self.cookie = SimpleCookie() + def get_uuid(self): + return self.uuid + def collapse_body(self): """Collapse self.body to a single string; replace it and return it.""" if isinstance(self.body, text_or_bytes): From 7adbde162353548d09947df7d5a4a19e2996c1a2 Mon Sep 17 00:00:00 2001 From: spagno Date: Thu, 19 Oct 2017 23:06:14 +0200 Subject: [PATCH 26/44] fixed request.uuid --- cherrypy/_cplogging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index a40f9855f..3a4a17382 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -262,7 +262,7 @@ def access(self): 'f': dict.get(inheaders, 'Referer', ''), 'a': dict.get(inheaders, 'User-Agent', ''), 'o': dict.get(inheaders, 'Host', '-'), - 'i': request.uuid, + 'i': response.uuid, 'z': self.time_z(), } if six.PY3: From 584d2fb28e538b54b53fc1e992ff0f6a5881754f Mon Sep 17 00:00:00 2001 From: spagno Date: Thu, 19 Oct 2017 23:08:00 +0200 Subject: [PATCH 27/44] fixed string --- cherrypy/_cplogging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 3a4a17382..05ceebb72 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -262,7 +262,7 @@ def access(self): 'f': dict.get(inheaders, 'Referer', ''), 'a': dict.get(inheaders, 'User-Agent', ''), 'o': dict.get(inheaders, 'Host', '-'), - 'i': response.uuid, + 'i': str(response.uuid), 'z': self.time_z(), } if six.PY3: From 256825ba3259de570d556a5d6911ff7dcaa39bd8 Mon Sep 17 00:00:00 2001 From: spagno Date: Thu, 19 Oct 2017 23:11:23 +0200 Subject: [PATCH 28/44] added get_uuid --- cherrypy/_cprequest.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/cherrypy/_cprequest.py b/cherrypy/_cprequest.py index e3459bee4..7c07e687a 100644 --- a/cherrypy/_cprequest.py +++ b/cherrypy/_cprequest.py @@ -902,7 +902,7 @@ def __init__(self): self.header_list = None self._body = [] self.time = time.time() - self._uuid = None + self._uuid = "" self.headers = httputil.HeaderMap() # Since we know all our keys are titled strings, we can @@ -967,7 +967,7 @@ def finalize(self): # Transform our header dict into a list of tuples. self.header_list = h = headers.output() - + self.uuid = self.get_uuid() cookie = self.cookie.output() if cookie: for line in cookie.split('\r\n'): From 31991d5d7ba3feadfe354184353918a7de8b540b Mon Sep 17 00:00:00 2001 From: spagno Date: Thu, 19 Oct 2017 23:13:50 +0200 Subject: [PATCH 29/44] Fixed double quoted strings --- cherrypy/_cprequest.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cherrypy/_cprequest.py b/cherrypy/_cprequest.py index 7c07e687a..a76fcf676 100644 --- a/cherrypy/_cprequest.py +++ b/cherrypy/_cprequest.py @@ -902,7 +902,7 @@ def __init__(self): self.header_list = None self._body = [] self.time = time.time() - self._uuid = "" + self._uuid = '' self.headers = httputil.HeaderMap() # Since we know all our keys are titled strings, we can From 2aea16eefccb74fc1845b2aa728286eed79d742f Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 12:37:36 +0300 Subject: [PATCH 30/44] Make time_z lazily evaluated for logging --- cherrypy/_cplogging.py | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 05ceebb72..2a763959a 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -263,7 +263,7 @@ def access(self): 'a': dict.get(inheaders, 'User-Agent', ''), 'o': dict.get(inheaders, 'Host', '-'), 'i': str(response.uuid), - 'z': self.time_z(), + 'z': LazyRfc3339UtcTime(), } if six.PY3: for k, v in atoms.items(): @@ -314,12 +314,6 @@ def time(self): return ('[%02d/%s/%04d:%02d:%02d:%02d]' % (now.day, month, now.year, now.hour, now.minute, now.second)) - @staticmethod - def time_z(): - """Return now() in RFC3339 UTC Format.""" - now = datetime.datetime.now() - return now.isoformat('T') + 'Z' - def _get_builtin_handler(self, log, key): for h in log.handlers: if getattr(h, '_cpbuiltin', None) == key: @@ -470,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' From 6c508d6b951102fd5c8c696e0fcf430687e720a3 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 13:13:06 +0300 Subject: [PATCH 31/44] Extend req w/ lazily evald on rend unique_id prop --- cherrypy/_cplogging.py | 2 +- cherrypy/_cprequest.py | 46 +++++++++++++++++++++++------------------- 2 files changed, 26 insertions(+), 22 deletions(-) diff --git a/cherrypy/_cplogging.py b/cherrypy/_cplogging.py index 2a763959a..1a72bdf5f 100644 --- a/cherrypy/_cplogging.py +++ b/cherrypy/_cplogging.py @@ -262,7 +262,7 @@ def access(self): 'f': dict.get(inheaders, 'Referer', ''), 'a': dict.get(inheaders, 'User-Agent', ''), 'o': dict.get(inheaders, 'Host', '-'), - 'i': str(response.uuid), + 'i': request.unique_id, 'z': LazyRfc3339UtcTime(), } if six.PY3: diff --git a/cherrypy/_cprequest.py b/cherrypy/_cprequest.py index a76fcf676..fea59d4cf 100644 --- a/cherrypy/_cprequest.py +++ b/cherrypy/_cprequest.py @@ -467,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, @@ -498,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: @@ -835,20 +840,6 @@ def __set__(self, obj, value): obj._body = value -class RequestUuid(object): - - """The UUIDv4.""" - def __get__(self, obj, objclass=None): - if obj is None: - # When calling on the class instead of instance... - return self - else: - return obj._uuid - - def __set__(self, obj, value): - obj._uuid = uuid.uuid4() - - class Response(object): """An HTTP Response, including status, headers, and body.""" @@ -894,9 +885,6 @@ class Response(object): stream = False """If False, buffer the response body.""" - uuid = RequestUuid() - """The uuidv4 (entity) of the HTTP request.""" - def __init__(self): self.status = None self.header_list = None @@ -914,9 +902,6 @@ def __init__(self): }) self.cookie = SimpleCookie() - def get_uuid(self): - return self.uuid - def collapse_body(self): """Collapse self.body to a single string; replace it and return it.""" if isinstance(self.body, text_or_bytes): @@ -967,7 +952,6 @@ def finalize(self): # Transform our header dict into a list of tuples. self.header_list = h = headers.output() - self.uuid = self.get_uuid() cookie = self.cookie.output() if cookie: for line in cookie.split('\r\n'): @@ -986,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 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 From f27d41a0afe831ee92fdf21315a5bc92c5d26acb Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 13:20:38 +0300 Subject: [PATCH 32/44] Drop bogus _cprequest.Response._uuid property --- cherrypy/_cprequest.py | 1 - 1 file changed, 1 deletion(-) diff --git a/cherrypy/_cprequest.py b/cherrypy/_cprequest.py index fea59d4cf..7319a3c9d 100644 --- a/cherrypy/_cprequest.py +++ b/cherrypy/_cprequest.py @@ -890,7 +890,6 @@ def __init__(self): self.header_list = None self._body = [] self.time = time.time() - self._uuid = '' self.headers = httputil.HeaderMap() # Since we know all our keys are titled strings, we can From c1876ce2c8bb059195f1942bf72960783d6822d6 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 13:22:06 +0300 Subject: [PATCH 33/44] Restore accidentally removed line separation --- cherrypy/_cprequest.py | 1 + 1 file changed, 1 insertion(+) diff --git a/cherrypy/_cprequest.py b/cherrypy/_cprequest.py index 7319a3c9d..55d6cda2b 100644 --- a/cherrypy/_cprequest.py +++ b/cherrypy/_cprequest.py @@ -951,6 +951,7 @@ def finalize(self): # Transform our header dict into a list of tuples. self.header_list = h = headers.output() + cookie = self.cookie.output() if cookie: for line in cookie.split('\r\n'): From bb137b710c4d401882be4a0c60762fa23e7e7fa4 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 13:30:58 +0300 Subject: [PATCH 34/44] Cleanup bogus tests --- cherrypy/test/test_logging.py | 39 ++++------------------------------- 1 file changed, 4 insertions(+), 35 deletions(-) diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index b43d726a1..fa0fde295 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -125,21 +125,6 @@ def testCustomLogFormat(self): cherrypy._cplogging.LogManager.access_log_format = original_logformat - def testUUIDv4ParameterLogFormat(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 = ( - '{i}' if six.PY3 - else - '%(i)s' - ) - - self.markLog() - self.getPage('/as_string') - self.assertValidUUIDv4() - - cherrypy._cplogging.LogManager.access_log_format = original_logformat - def testTimezLogFormat(self): """Test a customized access_log_format string, which is a feature of _cplogging.LogManager.access().""" original_logformat = cherrypy._cplogging.LogManager.access_log_format @@ -169,31 +154,15 @@ def testUUIDv4ParameterLogFormat(self): else '%(i)s' ) - - self.markLog() - self.getPage('/as_string') - self.assertValidUUIDv4() - - cherrypy._cplogging.LogManager.access_log_format = original_logformat - - def testTimezLogFormat(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} {z} "{r}" {s} {b} "{f}" "{a}" {o}' if six.PY3 + '{i} {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' + '%(i)s %(h)s %(l)s %(u)s %(z)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %(o)s' ) self.markLog() - self.getPage('/as_string', headers=[('Referer', 'REFERER'), - ('User-Agent', 'USERAGENT'), - ('Host', 'HOST')]) - self.assertLog(-1, '%s - - ' % self.interface()) - self.assertLog(-1, ' "GET /as_string HTTP/1.1" ' - '200 7 "REFERER" "USERAGENT" HOST') + self.getPage('/as_string') + self.assertValidUUIDv4() cherrypy._cplogging.LogManager.access_log_format = original_logformat From 131e53a1d0346a91e7a79a9c009bd8ae417e1bf8 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 13:32:19 +0300 Subject: [PATCH 35/44] Add missing import to logtest helper --- cherrypy/test/logtest.py | 1 + 1 file changed, 1 insertion(+) diff --git a/cherrypy/test/logtest.py b/cherrypy/test/logtest.py index ef34f9ff9..e88497a2c 100644 --- a/cherrypy/test/logtest.py +++ b/cherrypy/test/logtest.py @@ -2,6 +2,7 @@ import sys import time +from uuid import UUID import six From 438c6483996cf119ce3cb132a023201dcfcaaad0 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 13:38:28 +0300 Subject: [PATCH 36/44] Fix LazyUUID4 string rendering method --- cherrypy/_cprequest.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cherrypy/_cprequest.py b/cherrypy/_cprequest.py index 55d6cda2b..e0432a4d0 100644 --- a/cherrypy/_cprequest.py +++ b/cherrypy/_cprequest.py @@ -975,7 +975,7 @@ def check_timeout(self): class LazyUUID4(object): def __str__(self): """Return UUID4 and keep it for future calls.""" - return self.uuid4 + return str(self.uuid4) @property def uuid4(self): From da05e7a2063f4644ffcc960cfda92aed3e050009 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 13:42:08 +0300 Subject: [PATCH 37/44] Fix UUID4 test --- cherrypy/test/test_logging.py | 5 ----- 1 file changed, 5 deletions(-) diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index fa0fde295..7f7b84a82 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -154,11 +154,6 @@ def testUUIDv4ParameterLogFormat(self): else '%(i)s' ) - cherrypy._cplogging.LogManager.access_log_format = ( - '{i} {h} {l} {u} {z} "{r}" {s} {b} "{f}" "{a}" {o}' if six.PY3 - else - '%(i)s %(h)s %(l)s %(u)s %(z)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %(o)s' - ) self.markLog() self.getPage('/as_string') From 7e16a5aa8f5360479e1cbe1c38bc913272a52025 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 13:47:09 +0300 Subject: [PATCH 38/44] Use proper @mock.patch for log_format substitution --- cherrypy/test/test_logging.py | 15 +++++---------- 1 file changed, 5 insertions(+), 10 deletions(-) diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index 7f7b84a82..ba870eefc 100644 --- a/cherrypy/test/test_logging.py +++ b/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 @@ -144,23 +145,17 @@ def testTimezLogFormat(self): cherrypy._cplogging.LogManager.access_log_format = original_logformat + @mock.patch( + 'cherrypy._cplogging.LogManager.access_log_format', + '{i}' if six.PY3 else '%(i)s' + ) def testUUIDv4ParameterLogFormat(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 = ( - '{i}' if six.PY3 - else - '%(i)s' - ) - self.markLog() self.getPage('/as_string') self.assertValidUUIDv4() - cherrypy._cplogging.LogManager.access_log_format = original_logformat - def testEscapedOutput(self): # Test unicode in access log pieces. self.markLog() From 61e33561d4509f9fcb94d912f89049bce516e855 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 13:49:09 +0300 Subject: [PATCH 39/44] Fix docstring in test to be PEP257-compliant --- cherrypy/test/test_logging.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index ba870eefc..e783c6966 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -150,8 +150,7 @@ def testTimezLogFormat(self): '{i}' if six.PY3 else '%(i)s' ) def testUUIDv4ParameterLogFormat(self): - '''Test a customized access_log_format string, - which is a feature of _cplogging.LogManager.access() ''' + """Test rendering of UUID4 within access log.""" self.markLog() self.getPage('/as_string') self.assertValidUUIDv4() From 3e0af3c77ffdbdd55128b033fbc37afc44ced3b8 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 13:52:45 +0300 Subject: [PATCH 40/44] Use mock.patch for all logging tests --- cherrypy/test/test_logging.py | 30 ++++++++++++------------------ 1 file changed, 12 insertions(+), 18 deletions(-) diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index e783c6966..735c4071b 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -107,15 +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 %(z)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' - ) - self.markLog() self.getPage('/as_string', headers=[('Referer', 'REFERER'), ('User-Agent', 'USERAGENT'), @@ -124,17 +123,14 @@ 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().""" - original_logformat = cherrypy._cplogging.LogManager.access_log_format - 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' - ) - self.markLog() self.getPage('/as_string', headers=[('Referer', 'REFERER'), ('User-Agent', 'USERAGENT'), @@ -143,8 +139,6 @@ def testTimezLogFormat(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', '{i}' if six.PY3 else '%(i)s' From 7e41ee71df1e9ef3975236abd7f1550c6b0e829a Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 13:55:49 +0300 Subject: [PATCH 41/44] Improve UUID assertion in logging tests --- cherrypy/test/logtest.py | 13 ++++++++----- 1 file changed, 8 insertions(+), 5 deletions(-) diff --git a/cherrypy/test/logtest.py b/cherrypy/test/logtest.py index e88497a2c..9775ba653 100644 --- a/cherrypy/test/logtest.py +++ b/cherrypy/test/logtest.py @@ -176,12 +176,15 @@ def assertValidUUIDv4(self, marker=None): uuid_log = data[-1] uuid_obj = UUID(uuid_log, version=4) except (TypeError, ValueError): - msg = '%r not a valid UUIDv4' % uuid_log - self._handleLogError(msg, data, marker, log_chunk) + pass # it might be in other chunk else: - if str(uuid_obj) != uuid_log: - msg = '%r not a valid UUIDv4' % uuid_log - self._handleLogError(msg, data, marker, log_chunk) + 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'. From 8b21372aba54fbb08dea04467b81f950cf498168 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 14:10:02 +0300 Subject: [PATCH 42/44] Add test for Request.unique_id per-req property --- cherrypy/test/test_request_obj.py | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/cherrypy/test/test_request_obj.py b/cherrypy/test/test_request_obj.py index 44d4917a1..c03ba1c9f 100644 --- a/cherrypy/test/test_request_obj.py +++ b/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') From 4743879f470ec28c2c88036c2949222725225a01 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 14:12:51 +0300 Subject: [PATCH 43/44] Restore original access log custom format test --- cherrypy/test/test_logging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index 735c4071b..f07be9633 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -111,7 +111,7 @@ def testNormalYield(self): '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 %(z)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %(o)s' + '%(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().""" From 122a4841fa4ae385ef470ee374700d83a5666d88 Mon Sep 17 00:00:00 2001 From: Sviatoslav Sydorenko Date: Fri, 20 Oct 2017 14:55:54 +0300 Subject: [PATCH 44/44] Mock timez log test to be more precise --- cherrypy/test/test_logging.py | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/cherrypy/test/test_logging.py b/cherrypy/test/test_logging.py index f07be9633..d11c67c80 100644 --- a/cherrypy/test/test_logging.py +++ b/cherrypy/test/test_logging.py @@ -132,10 +132,15 @@ def testCustomLogFormat(self): def testTimezLogFormat(self): """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'), - ('Host', 'HOST')]) + + 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')