diff --git a/CHANGES/3767.feature b/CHANGES/3767.feature new file mode 100644 index 00000000000..0599080d0a9 --- /dev/null +++ b/CHANGES/3767.feature @@ -0,0 +1 @@ +Add ``AbstractAsyncAccessLogger`` to allow IO while logging. diff --git a/aiohttp/abc.py b/aiohttp/abc.py index 58817c0840c..d5234c77272 100644 --- a/aiohttp/abc.py +++ b/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.""" diff --git a/aiohttp/web_protocol.py b/aiohttp/web_protocol.py index 32881c40140..25afe935d2e 100644 --- a/aiohttp/web_protocol.py +++ b/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, diff --git a/docs/logging.rst b/docs/logging.rst index ac1ae404742..da4fad2c8b5 100644 --- a/docs/logging.rst +++ b/docs/logging.rst @@ -111,6 +111,28 @@ Example of a drop-in replacement for :class:`aiohttp.helpers.AccessLogger`:: ``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 diff --git a/tests/test_web_log.py b/tests/test_web_log.py index b1f1c7ceeb4..51809a7e94b 100644 --- a/tests/test_web_log.py +++ b/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'