From f8f896f625c4173599685e1e0e39227f910d739b Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 23 Mar 2023 08:35:31 -1000 Subject: [PATCH 01/11] Reduce access log overhead when logging is disabled If the logger was disabled the log message would be formatted and thrown away. Avoid formatting the log message when logging is not enabled at info level. --- aiohttp/web_log.py | 2 ++ tests/test_web_log.py | 14 ++++++++++++++ 2 files changed, 16 insertions(+) diff --git a/aiohttp/web_log.py b/aiohttp/web_log.py index 0fd862e6a84..bb022bbce97 100644 --- a/aiohttp/web_log.py +++ b/aiohttp/web_log.py @@ -189,6 +189,8 @@ def _format_line( return [(key, method(request, response, time)) for key, method in self._methods] def log(self, request: BaseRequest, response: StreamResponse, time: float) -> None: + if not self.logger.isEnabledFor(logging.INFO): + return try: fmt_info = self._format_line(request, response, time) diff --git a/tests/test_web_log.py b/tests/test_web_log.py index fa5fb27f744..56b4eb345d5 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -1,5 +1,6 @@ # type: ignore import datetime +import logging import platform import sys from typing import Any @@ -251,3 +252,16 @@ def log(self, request, response, time): resp = await client.get("/") assert 200 == resp.status assert msg == "contextvars: uuid" + + +def test_logger_does_nothing_when_disabled(caplog: pytest.LogCaptureFixture) -> None: + """Test that the logger does nothing when the log level is disabled.""" + mock_logger = logging.getLogger("test.aiohttp.log") + mock_logger.setLevel(logging.INFO) + access_logger = AccessLogger(mock_logger, "%a") + access_logger.log(None, None, 42) + assert "42" in caplog.text + caplog.clear() + mock_logger.setLevel(logging.WARNING) + access_logger.log(None, None, 42) + assert "42" not in caplog.text From 0f6927bed6302b8489f11716a614f4069abe5067 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 23 Mar 2023 08:38:33 -1000 Subject: [PATCH 02/11] add timeline --- CHANGES/7240.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 CHANGES/7240.misc diff --git a/CHANGES/7240.misc b/CHANGES/7240.misc new file mode 100644 index 00000000000..8bfabfaf46a --- /dev/null +++ b/CHANGES/7240.misc @@ -0,0 +1 @@ +Reduce access log overhead when the logger is not enabled. From 64db3ce52dce94910ea07af0e0cc1913dfbbb976 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 23 Mar 2023 08:42:54 -1000 Subject: [PATCH 03/11] add timeline --- 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 56b4eb345d5..1cf1ad1d19a 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -258,7 +258,7 @@ def test_logger_does_nothing_when_disabled(caplog: pytest.LogCaptureFixture) -> """Test that the logger does nothing when the log level is disabled.""" mock_logger = logging.getLogger("test.aiohttp.log") mock_logger.setLevel(logging.INFO) - access_logger = AccessLogger(mock_logger, "%a") + access_logger = AccessLogger(mock_logger) access_logger.log(None, None, 42) assert "42" in caplog.text caplog.clear() From f12e77d7f75700c884e256f2266c8e3783875c38 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 23 Mar 2023 09:00:25 -1000 Subject: [PATCH 04/11] fix test --- 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 1cf1ad1d19a..372bfd29970 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -258,7 +258,7 @@ def test_logger_does_nothing_when_disabled(caplog: pytest.LogCaptureFixture) -> """Test that the logger does nothing when the log level is disabled.""" mock_logger = logging.getLogger("test.aiohttp.log") mock_logger.setLevel(logging.INFO) - access_logger = AccessLogger(mock_logger) + access_logger = AccessLogger(mock_logger, "%b") access_logger.log(None, None, 42) assert "42" in caplog.text caplog.clear() From 2f341d15c2b0fb934024efb76999675c8f56b2b9 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 23 Mar 2023 09:20:09 -1000 Subject: [PATCH 05/11] mock --- tests/test_web_log.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/test_web_log.py b/tests/test_web_log.py index 372bfd29970..8e4602b2aa8 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -259,9 +259,9 @@ def test_logger_does_nothing_when_disabled(caplog: pytest.LogCaptureFixture) -> mock_logger = logging.getLogger("test.aiohttp.log") mock_logger.setLevel(logging.INFO) access_logger = AccessLogger(mock_logger, "%b") - access_logger.log(None, None, 42) + access_logger.log(mock.Mock(), mock.Mock(), 42) assert "42" in caplog.text caplog.clear() mock_logger.setLevel(logging.WARNING) - access_logger.log(None, None, 42) + access_logger.log(mock.Mock(), mock.Mock(), 42) assert "42" not in caplog.text From f533a69ba2fc7ccbd188969f3469169e37b360e7 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 23 Mar 2023 09:31:56 -1000 Subject: [PATCH 06/11] add timeline --- tests/test_web_log.py | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/tests/test_web_log.py b/tests/test_web_log.py index 8e4602b2aa8..af8dd6706e7 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -259,9 +259,13 @@ def test_logger_does_nothing_when_disabled(caplog: pytest.LogCaptureFixture) -> mock_logger = logging.getLogger("test.aiohttp.log") mock_logger.setLevel(logging.INFO) access_logger = AccessLogger(mock_logger, "%b") - access_logger.log(mock.Mock(), mock.Mock(), 42) - assert "42" in caplog.text + access_logger.log( + mock.Mock(name="mock_request"), mock.Mock(name="mock_response"), 42 + ) + assert "mock_request" in caplog.text caplog.clear() mock_logger.setLevel(logging.WARNING) - access_logger.log(mock.Mock(), mock.Mock(), 42) - assert "42" not in caplog.text + access_logger.log( + mock.Mock(name="mock_request"), mock.Mock(name="mock_response"), 42 + ) + assert "mock_request" not in caplog.text From 4a3a0c808aaa373db5400da7fcd8a58f40076648 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 23 Mar 2023 09:45:39 -1000 Subject: [PATCH 07/11] add timeline --- tests/test_web_log.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/test_web_log.py b/tests/test_web_log.py index af8dd6706e7..b6f0ce36a0a 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -262,10 +262,10 @@ def test_logger_does_nothing_when_disabled(caplog: pytest.LogCaptureFixture) -> access_logger.log( mock.Mock(name="mock_request"), mock.Mock(name="mock_response"), 42 ) - assert "mock_request" in caplog.text + assert "mock_response" in caplog.text caplog.clear() mock_logger.setLevel(logging.WARNING) access_logger.log( mock.Mock(name="mock_request"), mock.Mock(name="mock_response"), 42 ) - assert "mock_request" not in caplog.text + assert "mock_response" not in caplog.text From 680dbb2a19c0043adcd84ca5dd0d383ac4312739 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 23 Mar 2023 15:31:14 -1000 Subject: [PATCH 08/11] Update CHANGES/7240.misc Co-authored-by: Sviatoslav Sydorenko --- CHANGES/7240.misc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGES/7240.misc b/CHANGES/7240.misc index 8bfabfaf46a..e656f1369f6 100644 --- a/CHANGES/7240.misc +++ b/CHANGES/7240.misc @@ -1 +1 @@ -Reduce access log overhead when the logger is not enabled. +Turned access log into no-op when the logger is disabled. From 9392c92cf84d72fba8f097995a6f34087bfe9b18 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 23 Mar 2023 15:31:48 -1000 Subject: [PATCH 09/11] feature --- CHANGES/{7240.misc => 7240.feature} | 0 1 file changed, 0 insertions(+), 0 deletions(-) rename CHANGES/{7240.misc => 7240.feature} (100%) diff --git a/CHANGES/7240.misc b/CHANGES/7240.feature similarity index 100% rename from CHANGES/7240.misc rename to CHANGES/7240.feature From ef346020504d7f8168a53d59c90ae8c06e0a96b9 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 23 Mar 2023 15:32:37 -1000 Subject: [PATCH 10/11] add comment --- aiohttp/web_log.py | 1 + 1 file changed, 1 insertion(+) diff --git a/aiohttp/web_log.py b/aiohttp/web_log.py index bb022bbce97..633e9e3ae6b 100644 --- a/aiohttp/web_log.py +++ b/aiohttp/web_log.py @@ -190,6 +190,7 @@ def _format_line( def log(self, request: BaseRequest, response: StreamResponse, time: float) -> None: if not self.logger.isEnabledFor(logging.INFO): + # Avoid formatting the log line if it will not be emitted. return try: fmt_info = self._format_line(request, response, time) From 7eaa6fb05fa2e10233fcca32e7b065342bbf67dc Mon Sep 17 00:00:00 2001 From: Sam Bull Date: Sun, 16 Apr 2023 16:13:20 +0100 Subject: [PATCH 11/11] Update tests/test_web_log.py Co-authored-by: J. Nick Koston --- tests/test_web_log.py | 6 ------ 1 file changed, 6 deletions(-) diff --git a/tests/test_web_log.py b/tests/test_web_log.py index b6f0ce36a0a..6a09479f4b7 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -263,9 +263,3 @@ def test_logger_does_nothing_when_disabled(caplog: pytest.LogCaptureFixture) -> mock.Mock(name="mock_request"), mock.Mock(name="mock_response"), 42 ) assert "mock_response" in caplog.text - caplog.clear() - mock_logger.setLevel(logging.WARNING) - access_logger.log( - mock.Mock(name="mock_request"), mock.Mock(name="mock_response"), 42 - ) - assert "mock_response" not in caplog.text