Make access log use local time with timezone

PR #3860 by @NewUserHa Co-Authored-By: Sviatoslav Sydorenko <wk.cvs.github@sydorenko.org.ua>
aio-libs · Jun 22, 2019 · b05e2d3 · b05e2d3
1 parent 4273c7f
commit b05e2d3
Show file tree

Hide file tree

Showing 2 changed files with 39 additions and 23 deletions.
diff --git a/aiohttp/web_log.py b/aiohttp/web_log.py
@@ -4,6 +4,7 @@
 import os
 import re
 from collections import namedtuple
+from time import timezone
 from typing import Callable, Dict, Iterable, List, Tuple  # noqa
 
 from .abc import AbstractAccessLogger
@@ -149,9 +150,10 @@ def _format_a(request: BaseRequest,
     def _format_t(request: BaseRequest,
                   response: StreamResponse,
                   time: float) -> str:
-        now = datetime.datetime.utcnow()
+        tz = datetime.timezone(datetime.timedelta(seconds=-timezone))
+        now = datetime.datetime.now(tz)
         start_time = now - datetime.timedelta(seconds=time)
-        return start_time.strftime('[%d/%b/%Y:%H:%M:%S +0000]')
+        return start_time.strftime('[%d/%b/%Y:%H:%M:%S %z]')
 
     @staticmethod
     def _format_P(request: BaseRequest,

diff --git a/tests/test_web_log.py b/tests/test_web_log.py
@@ -43,13 +43,41 @@ def test_access_logger_format() -> None:
     Ref: https://stackoverflow.com/a/46102240/595220
     """,  # noqa: E501
 )
-def test_access_logger_atoms(mocker) -> None:
-    utcnow = datetime.datetime(1843, 1, 1, 0, 30)
-    mock_datetime = mocker.patch("aiohttp.datetime.datetime")
-    mock_getpid = mocker.patch("os.getpid")
-    mock_datetime.utcnow.return_value = utcnow
-    mock_getpid.return_value = 42
-    log_format = '%a %t %P %r %s %b %T %Tf %D "%{H1}i" "%{H2}i"'
+@pytest.mark.parametrize(
+    'log_format,expected,extra',
+    [
+        ('%t',
+         '[01/Jan/1843:00:29:56 +0800]',
+         {
+             'request_start_time': '[01/Jan/1843:00:29:56 +0800]'
+         }
+         ),
+        ('%a %t %P %r %s %b %T %Tf %D "%{H1}i" "%{H2}i"',
+         ('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"'),
+         {
+             '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,
+             'request_header': {'H1': 'a', 'H2': 'b'},
+         }
+         )
+    ]
+)
+def test_access_logger_atoms(monkeypatch, log_format, expected, extra) -> None:
+    class PatchedDatetime(datetime.datetime):
+        @staticmethod
+        def now(tz):
+            return datetime.datetime(1843, 1, 1, 0, 30, tzinfo=tz)
+    monkeypatch.setattr("datetime.datetime", PatchedDatetime)
+    monkeypatch.setattr("time.timezone", -28800)
+    monkeypatch.setattr("os.getpid", lambda: 42)
     mock_logger = mock.Mock()
     access_logger = AccessLogger(mock_logger, log_format)
     request = mock.Mock(headers={'H1': 'a', 'H2': 'b'},
@@ -59,20 +87,6 @@ def test_access_logger_atoms(mocker) -> None:
     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: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,
-        'request_header': {'H1': 'a', 'H2': 'b'},
-    }
 
     mock_logger.info.assert_called_with(expected, extra=extra)