[PR #9822/249df6e backport][3.11] Improve performance of the access logger when its disabled (#9828)

Author: bdraco

CHANGES/9822.feature.rst

@@ -0,0 +1 @@
+Added an :attr:`~aiohttp.abc.AbstractAccessLogger.enabled` property to :class:`aiohttp.abc.AbstractAccessLogger` to dynamically check if logging is enabled -- by :user:`bdraco`.

aiohttp/abc.py

@@ -231,10 +231,17 @@ async def write_headers(
 class AbstractAccessLogger(ABC):
     """Abstract writer to access log."""
 
+    __slots__ = ("logger", "log_format")
+
     def __init__(self, logger: logging.Logger, log_format: str) -> None:
         self.logger = logger
         self.log_format = log_format
 
     @abstractmethod
     def log(self, request: BaseRequest, response: StreamResponse, time: float) -> None:
         """Emit log to logger."""
+
+    @property
+    def enabled(self) -> bool:
+        """Check if logger is enabled."""
+        return True

aiohttp/web_log.py

@@ -188,10 +188,13 @@ def _format_line(
     ) -> Iterable[Tuple[str, Callable[[BaseRequest, StreamResponse, float], str]]]:
         return [(key, method(request, response, time)) for key, method in self._methods]
 
+    @property
+    def enabled(self) -> bool:
+        """Check if logger is enabled."""
+        # Avoid formatting the log line if it will not be emitted.
+        return self.logger.isEnabledFor(logging.INFO)
+
     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)
 

aiohttp/web_protocol.py

@@ -438,7 +438,7 @@ def force_close(self) -> None:
     def log_access(
         self, request: BaseRequest, response: StreamResponse, time: float
     ) -> None:
-        if self.access_logger is not None:
+        if self.access_logger is not None and self.access_logger.enabled:
             self.access_logger.log(request, response, self._loop.time() - time)
 
     def log_debug(self, *args: Any, **kw: Any) -> None:

docs/abc.rst

@@ -182,6 +182,15 @@ Abstract Access Logger
 
       :param float time: Time taken to serve the request.
 
+   .. attribute:: enabled
+
+        Return True if logger is enabled.
+
+        Override this property if logging is disabled to avoid the
+        overhead of calculating details to feed the logger.
+
+        This property may be omitted if logging is always enabled.
+
 
 Abstract Resolver
 -------------------------------

docs/logging.rst

@@ -115,6 +115,16 @@ Example of a drop-in replacement for the default access logger::
                            f'"{request.method} {request.path} '
                            f'done in {time}s: {response.status}')
 
+      @property
+      def enabled(self):
+          """Return True if logger is enabled.
+
+          Override this property if logging is disabled to avoid the
+          overhead of calculating details to feed the logger.
+
+          This property may be omitted if logging is always enabled.
+          """
+          return self.logger.isEnabledFor(logging.INFO)
 
 .. _gunicorn-accesslog:
 

tests/test_web_log.py

@@ -9,6 +9,7 @@
 import aiohttp
 from aiohttp import web
 from aiohttp.abc import AbstractAccessLogger
+from aiohttp.pytest_plugin import AiohttpClient, AiohttpServer
 from aiohttp.typedefs import Handler
 from aiohttp.web_log import AccessLogger
 
@@ -215,12 +216,42 @@ def log(self, request, response, time):
     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."""
+def test_access_logger_feeds_logger(caplog: pytest.LogCaptureFixture) -> None:
+    """Test that the logger still works."""
     mock_logger = logging.getLogger("test.aiohttp.log")
     mock_logger.setLevel(logging.INFO)
     access_logger = AccessLogger(mock_logger, "%b")
     access_logger.log(
         mock.Mock(name="mock_request"), mock.Mock(name="mock_response"), 42
     )
     assert "mock_response" in caplog.text
+
+
+async def test_logger_does_not_log_when_not_enabled(
+    aiohttp_server: AiohttpServer,
+    aiohttp_client: AiohttpClient,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    """Test logger does nothing when not enabled."""
+
+    async def handler(request: web.Request) -> web.Response:
+        return web.Response()
+
+    class Logger(AbstractAccessLogger):
+
+        def log(
+            self, request: web.BaseRequest, response: web.StreamResponse, time: float
+        ) -> None:
+            self.logger.critical("This should not be logged")  # pragma: no cover
+
+        @property
+        def enabled(self) -> bool:
+            return False
+
+    app = web.Application()
+    app.router.add_get("/", handler)
+    server = await aiohttp_server(app, access_log_class=Logger)
+    client = await aiohttp_client(server)
+    resp = await client.get("/")
+    assert 200 == resp.status
+    assert "This should not be logged" not in caplog.text