From 78a2fec6b220440c994a82f1f785ca33f565de7d Mon Sep 17 00:00:00 2001 From: Samuel Colvin Date: Mon, 13 May 2019 14:51:46 +0100 Subject: [PATCH] Rewrite access_logger to keep exception context (#3557) --- CHANGES/3557.feature | 1 + aiohttp/web_protocol.py | 64 ++++++++++++++++++++++++++--------------- docs/logging.rst | 9 ++++-- tests/test_web_log.py | 22 ++++++++++++++ 4 files changed, 70 insertions(+), 26 deletions(-) create mode 100644 CHANGES/3557.feature diff --git a/CHANGES/3557.feature b/CHANGES/3557.feature new file mode 100644 index 00000000000..9d2b10be0f7 --- /dev/null +++ b/CHANGES/3557.feature @@ -0,0 +1 @@ +Call ``AccessLogger.log`` with the current exception available from sys.exc_info(). diff --git a/aiohttp/web_protocol.py b/aiohttp/web_protocol.py index 94b0e243bf3..32881c40140 100644 --- a/aiohttp/web_protocol.py +++ b/aiohttp/web_protocol.py @@ -342,9 +342,10 @@ def force_close(self) -> None: def log_access(self, request: BaseRequest, response: StreamResponse, - time: float) -> None: + request_start: float) -> None: if self.access_logger is not None: - self.access_logger.log(request, response, time) + self.access_logger.log(request, response, + self._loop.time() - request_start) def log_debug(self, *args: Any, **kw: Any) -> None: if self.debug: @@ -402,8 +403,7 @@ async def start(self) -> None: message, payload = self._messages.popleft() - if self.access_log: - now = loop.time() + start = loop.time() manager.requests_count += 1 writer = StreamWriter(self, loop) @@ -420,41 +420,29 @@ async def start(self) -> None: reason=exc.reason, text=exc.text, headers=exc.headers) + reset = await self.finish_response(request, resp, start) except asyncio.CancelledError: self.log_debug('Ignored premature client disconnection') break except asyncio.TimeoutError as exc: self.log_debug('Request handler timed out.', exc_info=exc) resp = self.handle_error(request, 504) + reset = await self.finish_response(request, resp, start) except Exception as exc: resp = self.handle_error(request, 500, exc) + reset = await self.finish_response(request, resp, start) + else: + reset = await self.finish_response(request, resp, start) + # Drop the processed task from asyncio.Task.all_tasks() early del task - - try: - prepare_meth = resp.prepare - except AttributeError: - if resp is None: - raise RuntimeError("Missing return " - "statement on request handler") - else: - raise RuntimeError("Web-handler should return " - "a response instance, " - "got {!r}".format(resp)) - try: - await prepare_meth(request) - await resp.write_eof() - except ConnectionResetError: + if reset: self.log_debug('Ignored premature client disconnection 2') break # notify server about keep-alive self._keepalive = bool(resp.keep_alive) - # log access - if self.access_log: - self.log_access(request, resp, loop.time() - now) - # check payload if not payload.is_eof(): lingering_time = self._lingering_time @@ -514,6 +502,36 @@ async def start(self) -> None: if self.transport is not None and self._error_handler is None: self.transport.close() + async def finish_response(self, + request: BaseRequest, + resp: StreamResponse, + start_time: float) -> bool: + """ + Prepare the response and write_eof, then log access. This has to + be called within the context of any exception so the access logger + can get exception information. Returns True if the client disconnects + prematurely. + """ + try: + prepare_meth = resp.prepare + except AttributeError: + if resp is None: + raise RuntimeError("Missing return " + "statement on request handler") + else: + raise RuntimeError("Web-handler should return " + "a response instance, " + "got {!r}".format(resp)) + try: + await prepare_meth(request) + await resp.write_eof() + except ConnectionResetError: + self.log_access(request, resp, start_time) + return True + else: + self.log_access(request, resp, start_time) + return False + def handle_error(self, request: BaseRequest, status: int=500, diff --git a/docs/logging.rst b/docs/logging.rst index 721b5201cbf..ac1ae404742 100644 --- a/docs/logging.rst +++ b/docs/logging.rst @@ -105,6 +105,12 @@ Example of a drop-in replacement for :class:`aiohttp.helpers.AccessLogger`:: f'done in {time}s: {response.status}') +.. versionadded:: 4.0.0 + + +``AccessLogger.log()`` can now access any exception raised while processing +the request with ``sys.exc_info()``. + .. _gunicorn-accesslog: Gunicorn access logs @@ -123,9 +129,6 @@ a custom logging setup intercepting the ``'gunicorn.access'`` logger, accesslog_ should be set to ``'-'`` to prevent Gunicorn to create an empty access log file upon every startup. - - - Error logs ---------- diff --git a/tests/test_web_log.py b/tests/test_web_log.py index a76fedba351..b1f1c7ceeb4 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -1,5 +1,6 @@ import datetime import platform +import sys from unittest import mock import pytest @@ -156,3 +157,24 @@ def log(self, request, response, time): access_logger = Logger(mock_logger, '{request} {response} {time}') access_logger.log('request', 'response', 1) mock_logger.info.assert_called_with('request response 1') + + +async def test_exc_info_context(aiohttp_raw_server, aiohttp_client): + exc_msg = None + + class Logger(AbstractAccessLogger): + def log(self, request, response, time): + nonlocal exc_msg + exc_msg = '{0.__name__}: {1}'.format(*sys.exc_info()) + + async def handler(request): + raise RuntimeError('intentional runtime error') + + 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 == 500 + assert exc_msg == 'RuntimeError: intentional runtime error'