implementing AbstractAsyncAccessLogger (aio-libs#3767)

Author: samuelcolvin

CHANGES/3767.feature

@@ -0,0 +1 @@
+Add ``AbstractAsyncAccessLogger`` to allow IO while logging.

aiohttp/abc.py

@@ -206,3 +206,14 @@ def log(self,
             response: StreamResponse,
             time: float) -> None:
         """Emit log to logger."""
+
+
+class AbstractAsyncAccessLogger(ABC):
+    """Abstract asynchronous writer to access log."""
+
+    @abstractmethod
+    async def log(self,
+                  request: BaseRequest,
+                  response: StreamResponse,
+                  request_start: float) -> None:
+        """Emit log to logger."""

aiohttp/web_protocol.py

@@ -13,12 +13,17 @@
     Callable,
     Optional,
     Type,
+    Union,
     cast,
 )
 
 import yarl
 
-from .abc import AbstractAccessLogger, AbstractStreamWriter
+from .abc import (
+    AbstractAccessLogger,
+    AbstractAsyncAccessLogger,
+    AbstractStreamWriter,
+)
 from .base_protocol import BaseProtocol
 from .helpers import CeilTimeout, current_task
 from .http import (
@@ -50,6 +55,10 @@
                            BaseRequest]
 
 _RequestHandler = Callable[[BaseRequest], Awaitable[StreamResponse]]
+_AnyAbstractAccessLogger = Union[
+    Type[AbstractAsyncAccessLogger],
+    Type[AbstractAccessLogger],
+]
 
 
 ERROR = RawRequestMessage(
@@ -65,6 +74,22 @@ class PayloadAccessError(Exception):
     """Payload was accessed after response was sent."""
 
 
+class AccessLoggerWrapper(AbstractAsyncAccessLogger):
+    """
+    Wraps an AbstractAccessLogger so it behaves
+    like an AbstractAsyncAccessLogger.
+    """
+    def __init__(self, access_logger: AbstractAccessLogger):
+        self.access_logger = access_logger
+        super().__init__()
+
+    async def log(self,
+                  request: BaseRequest,
+                  response: StreamResponse,
+                  request_start: float) -> None:
+        self.access_logger.log(request, response, request_start)
+
+
 class RequestHandler(BaseProtocol):
     """HTTP protocol implementation.
 
@@ -120,7 +145,7 @@ def __init__(self, manager: 'Server', *,
                  keepalive_timeout: float=75.,  # NGINX default is 75 secs
                  tcp_keepalive: bool=True,
                  logger: Logger=server_logger,
-                 access_log_class: Type[AbstractAccessLogger]=AccessLogger,
+                 access_log_class: _AnyAbstractAccessLogger=AccessLogger,
                  access_log: Logger=access_logger,
                  access_log_format: str=AccessLogger.LOG_FORMAT,
                  debug: bool=False,
@@ -164,8 +189,11 @@ def __init__(self, manager: 'Server', *,
         self.debug = debug
         self.access_log = access_log
         if access_log:
-            self.access_logger = access_log_class(
-                access_log, access_log_format)  # type: Optional[AbstractAccessLogger]  # noqa
+            if issubclass(access_log_class, AbstractAsyncAccessLogger):
+                self.access_logger = access_log_class()  # type: Optional[AbstractAsyncAccessLogger]  # noqa
+            else:
+                access_logger = access_log_class(access_log, access_log_format)
+                self.access_logger = AccessLoggerWrapper(access_logger)
         else:
             self.access_logger = None
 
@@ -339,13 +367,13 @@ def force_close(self) -> None:
             self.transport.close()
             self.transport = None
 
-    def log_access(self,
-                   request: BaseRequest,
-                   response: StreamResponse,
-                   request_start: float) -> None:
+    async def log_access(self,
+                         request: BaseRequest,
+                         response: StreamResponse,
+                         request_start: float) -> None:
         if self.access_logger is not None:
-            self.access_logger.log(request, response,
-                                   self._loop.time() - request_start)
+            await self.access_logger.log(request, response,
+                                         self._loop.time() - request_start)
 
     def log_debug(self, *args: Any, **kw: Any) -> None:
         if self.debug:
@@ -526,10 +554,10 @@ async def finish_response(self,
             await prepare_meth(request)
             await resp.write_eof()
         except ConnectionResetError:
-            self.log_access(request, resp, start_time)
+            await self.log_access(request, resp, start_time)
             return True
         else:
-            self.log_access(request, resp, start_time)
+            await self.log_access(request, resp, start_time)
             return False
 
     def handle_error(self,

docs/logging.rst

@@ -111,6 +111,28 @@ Example of a drop-in replacement for the default access logger::
 ``AccessLogger.log()`` can now access any exception raised while processing
 the request with ``sys.exc_info()``.
 
+
+.. versionadded:: 4.0.0
+
+
+If your logging needs to perform IO you can instead inherit from
+:class:`aiohttp.abc.AbstractAsyncAccessLogger`::
+
+
+  from aiohttp.abc import AbstractAsyncAccessLogger
+
+  class AccessLogger(AbstractAsyncAccessLogger):
+
+      async def log(self, request, response, time):
+          logging_service = request.app['logging_service']
+          await logging_service.log(f'{request.remote} '
+                                    f'"{request.method} {request.path} '
+                                    f'done in {time}s: {response.status}')
+
+
+This also allows access to the results of coroutines on the ``request`` and
+``response``, e.g. ``request.text()``.
+
 .. _gunicorn-accesslog:
 
 Gunicorn access logs

tests/test_web_log.py

@@ -5,8 +5,9 @@
 
 import pytest
 
-from aiohttp.abc import AbstractAccessLogger
+from aiohttp.abc import AbstractAccessLogger, AbstractAsyncAccessLogger
 from aiohttp.web_log import AccessLogger
+from aiohttp.web_response import Response
 
 IS_PYPY = platform.python_implementation() == 'PyPy'
 
@@ -178,3 +179,24 @@ async def handler(request):
     resp = await cli.get('/path/to', headers={'Accept': 'text/html'})
     assert resp.status == 500
     assert exc_msg == 'RuntimeError: intentional runtime error'
+
+
+async def test_async_logger(aiohttp_raw_server, aiohttp_client):
+    msg = None
+
+    class Logger(AbstractAsyncAccessLogger):
+        async def log(self, request, response, time):
+            nonlocal msg
+            msg = '{}: {}'.format(request.path, response.status)
+
+    async def handler(request):
+        return Response(text='ok')
+
+    logger = mock.Mock()
+    server = await aiohttp_raw_server(handler,
+                                      access_log_class=Logger,
+                                      logger=logger)
+    cli = await aiohttp_client(server)
+    resp = await cli.get('/path/to', headers={'Accept': 'text/html'})
+    assert resp.status == 200
+    assert msg == '/path/to: 200'