From 4c2ff2cade183d3d0d4346b420d7b4c5eeef9c06 Mon Sep 17 00:00:00 2001 From: Andrew Svetlov Date: Fri, 9 Feb 2018 13:16:58 +0200 Subject: [PATCH] Fix #2641: Correctly process request start time and multiple request/response headers in access log extra --- CHANGES.rst | 3 ++- aiohttp/helpers.py | 11 ++++++++--- tests/test_helpers.py | 19 +++++++++++-------- 3 files changed, 21 insertions(+), 12 deletions(-) diff --git a/CHANGES.rst b/CHANGES.rst index 37d54145bfe..60094b8127b 100644 --- a/CHANGES.rst +++ b/CHANGES.rst @@ -71,7 +71,8 @@ Bugfixes - Fix default value of `access_log_format` argument in `web.run_app` (#2649) - Freeze sub-application on adding to parent app (#2656) - Do percent encoding for `.url_for()` parameters (#2668) - +- Correctly process request start time and multiple request/response + headers in access log extra (#2641) Improved Documentation ---------------------- diff --git a/aiohttp/helpers.py b/aiohttp/helpers.py index f2757817840..66cab71b9a3 100644 --- a/aiohttp/helpers.py +++ b/aiohttp/helpers.py @@ -306,7 +306,7 @@ class AccessLogger(AbstractAccessLogger): """ LOG_FORMAT_MAP = { 'a': 'remote_address', - 't': 'request_time', + 't': 'request_start_time', 'P': 'process_id', 'r': 'first_request_line', 's': 'response_status', @@ -403,7 +403,9 @@ def _format_a(request, response, time): @staticmethod def _format_t(request, response, time): - return datetime.datetime.utcnow().strftime('[%d/%b/%Y:%H:%M:%S +0000]') + now = datetime.datetime.utcnow() + start_time = now - datetime.timedelta(seconds=time) + return start_time.strftime('[%d/%b/%Y:%H:%M:%S +0000]') @staticmethod def _format_P(request, response, time): @@ -452,7 +454,10 @@ def log(self, request, response, time): if key.__class__ is str: extra[key] = value else: - extra[key[0]] = {key[1]: value} + k1, k2 = key + dct = extra.get(k1, {}) + dct[k2] = value + extra[k1] = dct self.logger.info(self._log_format % tuple(values), extra=extra) except Exception: diff --git a/tests/test_helpers.py b/tests/test_helpers.py index a181b83638b..5aa4a1ed6e7 100644 --- a/tests/test_helpers.py +++ b/tests/test_helpers.py @@ -125,31 +125,34 @@ def test_access_logger_format(): def test_access_logger_atoms(mocker): - mock_datetime = mocker.patch("aiohttp.helpers.datetime") + utcnow = datetime.datetime(1843, 1, 1, 0, 30) + mock_datetime = mocker.patch("aiohttp.helpers.datetime.datetime") mock_getpid = mocker.patch("os.getpid") - utcnow = datetime.datetime(1843, 1, 1, 0, 0) - mock_datetime.datetime.utcnow.return_value = utcnow + mock_datetime.utcnow.return_value = utcnow mock_getpid.return_value = 42 - log_format = '%a %t %P %r %s %b %T %Tf %D' + log_format = '%a %t %P %r %s %b %T %Tf %D "%{H1}i" "%{H2}i"' mock_logger = mock.Mock() access_logger = helpers.AccessLogger(mock_logger, log_format) - request = mock.Mock(headers={}, method="GET", path_qs="/path", + request = mock.Mock(headers={'H1': 'a', 'H2': 'b'}, + method="GET", path_qs="/path", version=(1, 1), remote="127.0.0.2") response = mock.Mock(headers={}, body_length=42, status=200) access_logger.log(request, response, 3.1415926) assert not mock_logger.exception.called - expected = ('127.0.0.2 [01/Jan/1843:00:00:00 +0000] <42> ' - 'GET /path HTTP/1.1 200 42 3 3.141593 3141593') + expected = ('127.0.0.2 [01/Jan/1843:00:29:56 +0000] <42> ' + 'GET /path HTTP/1.1 200 42 3 3.141593 3141593 "a" "b"') extra = { 'first_request_line': 'GET /path HTTP/1.1', 'process_id': '<42>', 'remote_address': '127.0.0.2', + 'request_start_time': '[01/Jan/1843:00:29:56 +0000]', 'request_time': 3, 'request_time_frac': '3.141593', 'request_time_micro': 3141593, 'response_size': 42, - 'response_status': 200 + 'response_status': 200, + 'request_header': {'H1': 'a', 'H2': 'b'}, } mock_logger.info.assert_called_with(expected, extra=extra)