Rewrite access_logger to keep exception context (#3557)

CHANGES/3557.feature

@@ -0,0 +1 @@
+Call ``AccessLogger.log`` with the current exception available from sys.exc_info().

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,

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
 ----------
 

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'