Fix #2641: Correctly process request start time and multiple request/…

…response headers in access log extra

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
 ----------------------

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:

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)