From 0aec3e71ea609dd13a7803bf39371aea0b4f9d39 Mon Sep 17 00:00:00 2001 From: Samuel Gaist Date: Sun, 5 Oct 2025 10:23:06 +0200 Subject: [PATCH 01/11] Make web logs timestamps DST aware This is done using the tm_gmtoff value rather than the static timezone information. --- CHANGES/11283.bugfix.rst | 2 ++ CONTRIBUTORS.txt | 1 + aiohttp/web_log.py | 4 +++- tests/test_web_log.py | 6 +++++- 4 files changed, 11 insertions(+), 2 deletions(-) create mode 100644 CHANGES/11283.bugfix.rst diff --git a/CHANGES/11283.bugfix.rst b/CHANGES/11283.bugfix.rst new file mode 100644 index 00000000000..90dda6a342b --- /dev/null +++ b/CHANGES/11283.bugfix.rst @@ -0,0 +1,2 @@ +Made `AccessLogger` use `tm_gmtoff` for timestamps to be 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..0b66ab0d498 100644 --- a/aiohttp/web_log.py +++ b/aiohttp/web_log.py @@ -138,7 +138,9 @@ 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)) + tz = datetime.timezone( + datetime.timedelta(seconds=time_mod.localtime().tm_gmtoff) + ) now = datetime.datetime.now(tz) 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..246a20c2702 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -2,6 +2,7 @@ import logging import platform import sys +import time from contextvars import ContextVar from typing import Dict, NoReturn, Optional from unittest import mock @@ -96,8 +97,11 @@ class PatchedDatetime(datetime.datetime): def now(cls, tz: Optional[datetime.tzinfo] = None) -> Self: return cls(1843, 1, 1, 0, 30, tzinfo=tz) + def patched_localtime(sec: int = None): + return time.struct_time((0, 0, 0, 0, 0, 0, 0, 0, 0, "test-tz", 28800)) + monkeypatch.setattr("datetime.datetime", PatchedDatetime) - monkeypatch.setattr("time.timezone", -28800) + monkeypatch.setattr("time.localtime", patched_localtime) monkeypatch.setattr("os.getpid", lambda: 42) mock_logger = mock.Mock() access_logger = AccessLogger(mock_logger, log_format) From 3139c5e678b45c4338dedaa1ef851fba0f1d0571 Mon Sep 17 00:00:00 2001 From: Samuel Gaist Date: Sun, 5 Oct 2025 10:45:05 +0200 Subject: [PATCH 02/11] fix: corrected based on linter report --- tests/test_web_log.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/test_web_log.py b/tests/test_web_log.py index 246a20c2702..6d3020609c5 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -97,7 +97,7 @@ class PatchedDatetime(datetime.datetime): def now(cls, tz: Optional[datetime.tzinfo] = None) -> Self: return cls(1843, 1, 1, 0, 30, tzinfo=tz) - def patched_localtime(sec: int = None): + def patched_localtime(sec: Optional[int] = None) -> time.struct_time: return time.struct_time((0, 0, 0, 0, 0, 0, 0, 0, 0, "test-tz", 28800)) monkeypatch.setattr("datetime.datetime", PatchedDatetime) From dee99b906ea2dbd1edb1351a84ad56a6349daaf7 Mon Sep 17 00:00:00 2001 From: Samuel Gaist Date: Sun, 5 Oct 2025 19:04:10 +0200 Subject: [PATCH 03/11] Apply suggestion from @webknjaz MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: 🇺🇦 Sviatoslav Sydorenko (Святослав Сидоренко) --- CHANGES/11283.bugfix.rst | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGES/11283.bugfix.rst b/CHANGES/11283.bugfix.rst index 90dda6a342b..108d1ee2e81 100644 --- a/CHANGES/11283.bugfix.rst +++ b/CHANGES/11283.bugfix.rst @@ -1,2 +1,3 @@ Made `AccessLogger` use `tm_gmtoff` for timestamps to be aware of DST. + -- by :user:`sgaist` From 484e8ce2c056aa0cda4e3e88ee6a7bb9652df538 Mon Sep 17 00:00:00 2001 From: Samuel Gaist Date: Sun, 5 Oct 2025 15:00:19 +0200 Subject: [PATCH 04/11] fix: corrected sign used for seconds value --- aiohttp/web_log.py | 2 +- tests/test_web_log.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/aiohttp/web_log.py b/aiohttp/web_log.py index 0b66ab0d498..d9c8d199c35 100644 --- a/aiohttp/web_log.py +++ b/aiohttp/web_log.py @@ -139,7 +139,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.localtime().tm_gmtoff) + datetime.timedelta(seconds=-time_mod.localtime().tm_gmtoff) ) now = datetime.datetime.now(tz) start_time = now - datetime.timedelta(seconds=time) diff --git a/tests/test_web_log.py b/tests/test_web_log.py index 6d3020609c5..515479e9960 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -98,7 +98,7 @@ def now(cls, tz: Optional[datetime.tzinfo] = None) -> Self: return cls(1843, 1, 1, 0, 30, tzinfo=tz) def patched_localtime(sec: Optional[int] = None) -> time.struct_time: - return time.struct_time((0, 0, 0, 0, 0, 0, 0, 0, 0, "test-tz", 28800)) + return time.struct_time((0, 0, 0, 0, 0, 0, 0, 0, 0, "test-tz", -28800)) monkeypatch.setattr("datetime.datetime", PatchedDatetime) monkeypatch.setattr("time.localtime", patched_localtime) From 726bfa6b192f0e9e1f9c2910072ac871a9a9b41e Mon Sep 17 00:00:00 2001 From: Samuel Gaist Date: Sun, 5 Oct 2025 15:02:39 +0200 Subject: [PATCH 05/11] fix: corrected changes file formating --- CHANGES/11283.bugfix.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGES/11283.bugfix.rst b/CHANGES/11283.bugfix.rst index 108d1ee2e81..06024eda202 100644 --- a/CHANGES/11283.bugfix.rst +++ b/CHANGES/11283.bugfix.rst @@ -1,3 +1,3 @@ -Made `AccessLogger` use `tm_gmtoff` for timestamps to be aware of DST. +Made ``AccessLogger`` use ``tm_gmtoff` for timestamps to be aware of DST. -- by :user:`sgaist` From d7319a723a4598ee052a1cacc8d92bd3820930ee Mon Sep 17 00:00:00 2001 From: Samuel Gaist Date: Sun, 5 Oct 2025 19:44:01 +0200 Subject: [PATCH 06/11] fix: add missing backtick in change file --- CHANGES/11283.bugfix.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGES/11283.bugfix.rst b/CHANGES/11283.bugfix.rst index 06024eda202..0614bfad51c 100644 --- a/CHANGES/11283.bugfix.rst +++ b/CHANGES/11283.bugfix.rst @@ -1,3 +1,3 @@ -Made ``AccessLogger`` use ``tm_gmtoff` for timestamps to be aware of DST. +Made ``AccessLogger`` use ``tm_gmtoff`` for timestamps to be aware of DST. -- by :user:`sgaist` From 66157063234b51a65baf74aade6e10a1c8c0537e Mon Sep 17 00:00:00 2001 From: Samuel Gaist Date: Mon, 6 Oct 2025 00:38:56 +0200 Subject: [PATCH 07/11] refactor: reimplement timezone discovery localtime does not guarantee to of have a valid tm_gmtoff. --- aiohttp/web_log.py | 7 +- tests/test_web_log.py | 156 ++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 152 insertions(+), 11 deletions(-) diff --git a/aiohttp/web_log.py b/aiohttp/web_log.py index d9c8d199c35..b9235c8924b 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,10 +137,8 @@ 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.localtime().tm_gmtoff) - ) - now = datetime.datetime.now(tz) + tz = datetime.datetime.now(datetime.timezone.utc).astimezone() + now = datetime.datetime.now(tz.tzinfo) 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 515479e9960..5ef7e4b255f 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -2,12 +2,12 @@ import logging import platform import sys -import time from contextvars import ContextVar from typing import Dict, NoReturn, Optional from unittest import mock import pytest +from freezegun import freeze_time import aiohttp from aiohttp import web @@ -92,16 +92,22 @@ def test_access_logger_atoms( expected: str, extra: Dict[str, object], ) -> None: + class TestTimeZone(datetime.tzinfo): + def __init__(self): + self.stdoffset = datetime.timedelta(hours=8) + + def utcoffset(self, dt): + return self.stdoffset + + def dst(self, dt): + return datetime.timedelta(0) + class PatchedDatetime(datetime.datetime): @classmethod def now(cls, tz: Optional[datetime.tzinfo] = None) -> Self: - return cls(1843, 1, 1, 0, 30, tzinfo=tz) - - def patched_localtime(sec: Optional[int] = None) -> time.struct_time: - return time.struct_time((0, 0, 0, 0, 0, 0, 0, 0, 0, "test-tz", -28800)) + return cls(1843, 1, 1, 0, 30, tzinfo=TestTimeZone()) monkeypatch.setattr("datetime.datetime", PatchedDatetime) - monkeypatch.setattr("time.localtime", patched_localtime) monkeypatch.setattr("os.getpid", lambda: 42) mock_logger = mock.Mock() access_logger = AccessLogger(mock_logger, log_format) @@ -119,6 +125,144 @@ def patched_localtime(sec: Optional[int] = None) -> time.struct_time: 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): + self.std_offset = datetime.timedelta(hours=1) + + def utcoffset(self, dt): + return self.std_offset + self.dst(dt) + + def dst(self, dt): + if is_dst: + return datetime.timedelta(hours=1) + else: + return datetime.timedelta(0) + + 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() From fcac70bb9f8c162dddcdf91b9a44605845673b7a Mon Sep 17 00:00:00 2001 From: Sam Bull Date: Mon, 6 Oct 2025 15:42:27 +0100 Subject: [PATCH 08/11] Update aiohttp/web_log.py --- aiohttp/web_log.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/aiohttp/web_log.py b/aiohttp/web_log.py index b9235c8924b..d92a356e66d 100644 --- a/aiohttp/web_log.py +++ b/aiohttp/web_log.py @@ -137,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.datetime.now(datetime.timezone.utc).astimezone() - now = datetime.datetime.now(tz.tzinfo) + 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]") From 986efbdb387599bf2b7ae7087dec5ebe4784253c Mon Sep 17 00:00:00 2001 From: Sam Bull Date: Mon, 6 Oct 2025 15:43:10 +0100 Subject: [PATCH 09/11] Update CHANGES/11283.bugfix.rst --- CHANGES/11283.bugfix.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGES/11283.bugfix.rst b/CHANGES/11283.bugfix.rst index 0614bfad51c..9f25fad0158 100644 --- a/CHANGES/11283.bugfix.rst +++ b/CHANGES/11283.bugfix.rst @@ -1,3 +1,3 @@ -Made ``AccessLogger`` use ``tm_gmtoff`` for timestamps to be aware of DST. +Made ``AccessLogger`` timestamps aware of DST. -- by :user:`sgaist` From 62c079f4373dc3aa1daf54ad59fd1f72cfb66cef Mon Sep 17 00:00:00 2001 From: Samuel Gaist Date: Mon, 6 Oct 2025 22:15:23 +0200 Subject: [PATCH 10/11] fix: corrected mypy reports --- tests/test_web_log.py | 21 +++++++++++++++------ 1 file changed, 15 insertions(+), 6 deletions(-) diff --git a/tests/test_web_log.py b/tests/test_web_log.py index 5ef7e4b255f..86087aabd6d 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -93,15 +93,18 @@ def test_access_logger_atoms( extra: Dict[str, object], ) -> None: class TestTimeZone(datetime.tzinfo): - def __init__(self): + def __init__(self) -> None: self.stdoffset = datetime.timedelta(hours=8) - def utcoffset(self, dt): + def utcoffset(self, dt: datetime.datetime | None) -> datetime.timedelta: return self.stdoffset - def dst(self, dt): + 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: @@ -219,18 +222,24 @@ def test_access_logger_atoms_dst( ) -> None: class TestTimeZone(datetime.tzinfo): - def __init__(self): + def __init__(self) -> None: self.std_offset = datetime.timedelta(hours=1) - def utcoffset(self, dt): + def utcoffset(self, dt: datetime.datetime | None) -> datetime.timedelta: return self.std_offset + self.dst(dt) - def dst(self, 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" + class PatchedDatetime(datetime.datetime): @classmethod def now(cls, tz: Optional[datetime.tzinfo] = None) -> Self: From 90e660002f79e0f300c56734b6a84c443a495bed Mon Sep 17 00:00:00 2001 From: Samuel Gaist Date: Mon, 6 Oct 2025 22:16:18 +0200 Subject: [PATCH 11/11] fix: add missing astimezone method in subclass --- tests/test_web_log.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/tests/test_web_log.py b/tests/test_web_log.py index 86087aabd6d..e74ce252a4f 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -110,6 +110,9 @@ class PatchedDatetime(datetime.datetime): def now(cls, tz: Optional[datetime.tzinfo] = None) -> Self: 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("os.getpid", lambda: 42) mock_logger = mock.Mock() @@ -240,6 +243,9 @@ def tzname(self, dt: datetime.datetime | None) -> str: 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: