diff --git a/CHANGES/11283.bugfix.rst b/CHANGES/11283.bugfix.rst new file mode 100644 index 00000000000..9f25fad0158 --- /dev/null +++ b/CHANGES/11283.bugfix.rst @@ -0,0 +1,3 @@ +Made ``AccessLogger`` timestamps aware of DST. + +-- by :user:`sgaist` diff --git a/CONTRIBUTORS.txt b/CONTRIBUTORS.txt index 033af03c21a..87c23c80b1f 100644 --- a/CONTRIBUTORS.txt +++ b/CONTRIBUTORS.txt @@ -317,6 +317,7 @@ Roman Postnov Rong Zhang Samir Akarioh Samuel Colvin +Samuel Gaist Sean Hunt Sebastian Acuna Sebastian Hanula diff --git a/aiohttp/web_log.py b/aiohttp/web_log.py index aff1a73a81b..d92a356e66d 100644 --- a/aiohttp/web_log.py +++ b/aiohttp/web_log.py @@ -3,7 +3,6 @@ import logging import os import re -import time as time_mod from collections import namedtuple from typing import Any, Callable, Dict, Iterable, List, Tuple # noqa @@ -138,8 +137,7 @@ def _format_a(request: BaseRequest, response: StreamResponse, time: float) -> st @staticmethod def _format_t(request: BaseRequest, response: StreamResponse, time: float) -> str: - tz = datetime.timezone(datetime.timedelta(seconds=-time_mod.timezone)) - now = datetime.datetime.now(tz) + now = datetime.datetime.now(datetime.timezone.utc).astimezone() start_time = now - datetime.timedelta(seconds=time) return start_time.strftime("[%d/%b/%Y:%H:%M:%S %z]") diff --git a/tests/test_web_log.py b/tests/test_web_log.py index 6456735de4a..e74ce252a4f 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -7,6 +7,7 @@ from unittest import mock import pytest +from freezegun import freeze_time import aiohttp from aiohttp import web @@ -91,13 +92,28 @@ def test_access_logger_atoms( expected: str, extra: Dict[str, object], ) -> None: + class TestTimeZone(datetime.tzinfo): + def __init__(self) -> None: + self.stdoffset = datetime.timedelta(hours=8) + + def utcoffset(self, dt: datetime.datetime | None) -> datetime.timedelta: + return self.stdoffset + + def dst(self, dt: datetime.datetime | None) -> datetime.timedelta: + return datetime.timedelta(0) + + def tzname(self, dt: datetime.datetime | None) -> str: + return "test-tz" + class PatchedDatetime(datetime.datetime): @classmethod def now(cls, tz: Optional[datetime.tzinfo] = None) -> Self: - return cls(1843, 1, 1, 0, 30, tzinfo=tz) + return cls(1843, 1, 1, 0, 30, tzinfo=TestTimeZone()) + + def astimezone(self, tz: datetime.tzinfo | None = None) -> Self: + return self 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) @@ -115,6 +131,153 @@ def now(cls, tz: Optional[datetime.tzinfo] = None) -> Self: mock_logger.info.assert_called_with(expected, extra=extra) +@pytest.mark.skipif( + IS_PYPY, + reason=""" + Because of patching :py:class:`datetime.datetime`, under PyPy it + fails in :py:func:`isinstance` call in + :py:meth:`datetime.datetime.__sub__` (called from + :py:meth:`aiohttp.AccessLogger._format_t`): + + *** TypeError: isinstance() arg 2 must be a class, type, or tuple of classes and types + + (Pdb) from datetime import datetime + (Pdb) isinstance(now, datetime) + *** TypeError: isinstance() arg 2 must be a class, type, or tuple of classes and types + (Pdb) datetime.__class__ + + (Pdb) isinstance(now, datetime.__class__) + False + + Ref: https://bitbucket.org/pypy/pypy/issues/1187/call-to-isinstance-in-__sub__-self-other + Ref: https://github.com/celery/celery/issues/811 + Ref: https://stackoverflow.com/a/46102240/595220 + """, +) +@pytest.mark.parametrize( + "input_date,is_dst,log_format,expected,extra", + [ + ( + "2011-09-19 02:30:00", + True, + "%t", + "[19/Sep/2011:02:29:56 +0200]", + {"request_start_time": "[19/Sep/2011:02:29:56 +0200]"}, + ), + ( + "2011-12-19 02:30:00", + False, + "%t", + "[19/Dec/2011:02:29:56 +0100]", + {"request_start_time": "[19/Dec/2011:02:29:56 +0100]"}, + ), + ( + "2011-09-19 02:30:00", + True, + '%a %t %P %r %s %b %T %Tf %D "%{H1}i" "%{H2}i"', + ( + "127.0.0.2 [19/Sep/2011:02:29:56 +0200] <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": "[19/Sep/2011:02:29:56 +0200]", + "request_time": "3", + "request_time_frac": "3.141593", + "request_time_micro": "3141593", + "response_size": 42, + "response_status": 200, + "request_header": {"H1": "a", "H2": "b"}, + }, + ), + ( + "2011-12-19 02:30:00", + False, + '%a %t %P %r %s %b %T %Tf %D "%{H1}i" "%{H2}i"', + ( + "127.0.0.2 [19/Dec/2011:02:29:56 +0100] <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": "[19/Dec/2011:02:29:56 +0100]", + "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_dst( + monkeypatch: pytest.MonkeyPatch, + input_date: str, + is_dst: int, + log_format: str, + expected: str, + extra: Dict[str, object], +) -> None: + + class TestTimeZone(datetime.tzinfo): + def __init__(self) -> None: + self.std_offset = datetime.timedelta(hours=1) + + def utcoffset(self, dt: datetime.datetime | None) -> datetime.timedelta: + return self.std_offset + self.dst(dt) + + def dst(self, dt: datetime.datetime | None) -> datetime.timedelta: + if is_dst: + return datetime.timedelta(hours=1) + else: + return datetime.timedelta(0) + + def tzname(self, dt: datetime.datetime | None) -> str: + if is_dst: + return "test-dst" + else: + return "test-std" + + def astimezone(self, tz: datetime.tzinfo | None = None) -> Self: + return self + + class PatchedDatetime(datetime.datetime): + @classmethod + def now(cls, tz: Optional[datetime.tzinfo] = None) -> Self: + dt = datetime.datetime.strptime(input_date, "%Y-%m-%d %H:%M:%S") + hour = dt.hour + 1 + if is_dst: + hour = dt.hour + 2 + return cls( + dt.year, dt.month, dt.day, hour, dt.minute, tzinfo=TestTimeZone() + ) + + monkeypatch.setattr("datetime.datetime", PatchedDatetime) + 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"}, + method="GET", + path_qs="/path", + version=aiohttp.HttpVersion(1, 1), + remote="127.0.0.2", + ) + response = mock.Mock(headers={}, body_length=42, status=200) + + with freeze_time(input_date): + access_logger.log(request, response, 3.1415926) + assert not mock_logger.exception.called, mock_logger.exception.call_args + + mock_logger.info.assert_called_with(expected, extra=extra) + + def test_access_logger_dicts() -> None: log_format = "%{User-Agent}i %{Content-Length}o %{None}i" mock_logger = mock.Mock()