[PR #10332/a0e64bb4 backport][3.12] Log the remote that generates request errors (#10338)

Author: patchback[bot]

CHANGES/10332.feature.rst

@@ -0,0 +1 @@
+Improved logging of HTTP protocol errors to include the remote address -- by :user:`bdraco`.

aiohttp/web_protocol.py

@@ -694,9 +694,13 @@ def handle_error(
             # or encrypted traffic to an HTTP port. This is expected
             # to happen when connected to the public internet so we log
             # it at the debug level as to not fill logs with noise.
-            self.logger.debug("Error handling request", exc_info=exc)
+            self.logger.debug(
+                "Error handling request from %s", request.remote, exc_info=exc
+            )
         else:
-            self.log_exception("Error handling request", exc_info=exc)
+            self.log_exception(
+                "Error handling request from %s", request.remote, exc_info=exc
+            )
 
         # some data already got sent, connection is broken
         if request.writer.output_size > 0:

tests/test_web_server.py

@@ -56,7 +56,9 @@ async def handler(request):
     assert txt.startswith("500 Internal Server Error")
     assert "Traceback" not in txt
 
-    logger.exception.assert_called_with("Error handling request", exc_info=exc)
+    logger.exception.assert_called_with(
+        "Error handling request from %s", cli.host, exc_info=exc
+    )
 
 
 async def test_raw_server_logs_invalid_method_with_loop_debug(
@@ -85,7 +87,9 @@ async def handler(request: web.BaseRequest) -> NoReturn:
     # on the first request since the client may
     # be probing for TLS/SSL support which is
     # expected to fail
-    logger.debug.assert_called_with("Error handling request", exc_info=exc)
+    logger.debug.assert_called_with(
+        "Error handling request from %s", cli.host, exc_info=exc
+    )
     logger.debug.reset_mock()
 
     # Now make another connection to the server
@@ -99,7 +103,9 @@ async def handler(request: web.BaseRequest) -> NoReturn:
     # on the first request since the client may
     # be probing for TLS/SSL support which is
     # expected to fail
-    logger.debug.assert_called_with("Error handling request", exc_info=exc)
+    logger.debug.assert_called_with(
+        "Error handling request from %s", cli.host, exc_info=exc
+    )
 
 
 async def test_raw_server_logs_invalid_method_without_loop_debug(
@@ -128,7 +134,9 @@ async def handler(request: web.BaseRequest) -> NoReturn:
     # on the first request since the client may
     # be probing for TLS/SSL support which is
     # expected to fail
-    logger.debug.assert_called_with("Error handling request", exc_info=exc)
+    logger.debug.assert_called_with(
+        "Error handling request from %s", cli.host, exc_info=exc
+    )
 
 
 async def test_raw_server_logs_invalid_method_second_request(
@@ -159,7 +167,9 @@ async def handler(request: web.BaseRequest) -> web.Response:
     # BadHttpMethod should be logged as an exception
     # if its not the first request since we know
     # that the client already was speaking HTTP
-    logger.exception.assert_called_with("Error handling request", exc_info=exc)
+    logger.exception.assert_called_with(
+        "Error handling request from %s", cli.host, exc_info=exc
+    )
 
 
 async def test_raw_server_logs_bad_status_line_as_exception(
@@ -184,7 +194,9 @@ async def handler(request: web.BaseRequest) -> NoReturn:
     txt = await resp.text()
     assert "Traceback (most recent call last):\n" not in txt
 
-    logger.exception.assert_called_with("Error handling request", exc_info=exc)
+    logger.exception.assert_called_with(
+        "Error handling request from %s", cli.host, exc_info=exc
+    )
 
 
 async def test_raw_server_handler_timeout(
@@ -254,7 +266,9 @@ async def handler(request):
     txt = await resp.text()
     assert "Traceback (most recent call last):\n" in txt
 
-    logger.exception.assert_called_with("Error handling request", exc_info=exc)
+    logger.exception.assert_called_with(
+        "Error handling request from %s", cli.host, exc_info=exc
+    )
 
 
 async def test_raw_server_html_exception(aiohttp_raw_server, aiohttp_client):
@@ -278,7 +292,9 @@ async def handler(request):
         "</body></html>\n"
     )
 
-    logger.exception.assert_called_with("Error handling request", exc_info=exc)
+    logger.exception.assert_called_with(
+        "Error handling request from %s", cli.host, exc_info=exc
+    )
 
 
 async def test_raw_server_html_exception_debug(aiohttp_raw_server, aiohttp_client):
@@ -302,7 +318,9 @@ async def handler(request):
         "<pre>Traceback (most recent call last):\n"
     )
 
-    logger.exception.assert_called_with("Error handling request", exc_info=exc)
+    logger.exception.assert_called_with(
+        "Error handling request from %s", cli.host, exc_info=exc
+    )
 
 
 async def test_handler_cancellation(unused_port_socket: socket.socket) -> None: