[PR #10055/c11fe96 backport][3.11] Downgrade logging of invalid HTTP methods on first request to debug level (#10064)

Author: bdraco

CHANGES/10055.misc.rst

@@ -0,0 +1,3 @@
+Downgraded logging of invalid HTTP method exceptions on the first request to debug level -- by :user:`bdraco`.
+
+HTTP requests starting with an invalid method are relatively common, especially when connected to the public internet, because browsers or other clients may try to speak SSL to a plain-text server or vice-versa. These exceptions can quickly fill the log with noise when nothing is wrong.

aiohttp/_http_parser.pyx

@@ -23,6 +23,7 @@ from aiohttp.helpers import DEBUG, set_exception
 
 from .http_exceptions import (
     BadHttpMessage,
+    BadHttpMethod,
     BadStatusLine,
     ContentLengthError,
     InvalidHeader,
@@ -831,8 +832,9 @@ cdef parser_error_from_errno(cparser.llhttp_t* parser, data, pointer):
                  cparser.HPE_INVALID_EOF_STATE,
                  cparser.HPE_INVALID_TRANSFER_ENCODING}:
         return BadHttpMessage(err_msg)
+    elif errno == cparser.HPE_INVALID_METHOD:
+        return BadHttpMethod(error=err_msg)
     elif errno in {cparser.HPE_INVALID_STATUS,
-                   cparser.HPE_INVALID_METHOD,
                    cparser.HPE_INVALID_VERSION}:
         return BadStatusLine(error=err_msg)
     elif errno == cparser.HPE_INVALID_URL:

aiohttp/http_exceptions.py

@@ -101,5 +101,12 @@ def __init__(self, line: str = "", error: Optional[str] = None) -> None:
         self.line = line
 
 
+class BadHttpMethod(BadStatusLine):
+    """Invalid HTTP method in status line."""
+
+    def __init__(self, line: str = "", error: Optional[str] = None) -> None:
+        super().__init__(line, error or f"Bad HTTP method in status line {line!r}")
+
+
 class InvalidURLError(BadHttpMessage):
     pass

aiohttp/http_parser.py

@@ -38,6 +38,7 @@
 )
 from .http_exceptions import (
     BadHttpMessage,
+    BadHttpMethod,
     BadStatusLine,
     ContentEncodingError,
     ContentLengthError,
@@ -576,7 +577,7 @@ def parse_message(self, lines: List[bytes]) -> RawRequestMessage:
         try:
             method, path, version = line.split(" ", maxsplit=2)
         except ValueError:
-            raise BadStatusLine(line) from None
+            raise BadHttpMethod(line) from None
 
         if len(path) > self.max_line_size:
             raise LineTooLong(
@@ -585,7 +586,7 @@ def parse_message(self, lines: List[bytes]) -> RawRequestMessage:
 
         # method
         if not TOKENRE.fullmatch(method):
-            raise BadStatusLine(method)
+            raise BadHttpMethod(method)
 
         # version
         match = VERSRE.fullmatch(version)

aiohttp/web_protocol.py

@@ -35,6 +35,7 @@
     RawRequestMessage,
     StreamWriter,
 )
+from .http_exceptions import BadHttpMethod
 from .log import access_logger, server_logger
 from .streams import EMPTY_PAYLOAD, StreamReader
 from .tcp_helpers import tcp_keepalive
@@ -687,7 +688,18 @@ def handle_error(
         Returns HTTP response with specific status code. Logs additional
         information. It always closes current connection.
         """
-        self.log_exception("Error handling request", exc_info=exc)
+        if (
+            self._manager
+            and self._manager.requests_count == 1
+            and isinstance(exc, BadHttpMethod)
+        ):
+            # BadHttpMethod is common when a client sends non-HTTP
+            # 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)
+        else:
+            self.log_exception("Error handling request", exc_info=exc)
 
         # some data already got sent, connection is broken
         if request.writer.output_size > 0:

tests/test_http_parser.py

@@ -965,7 +965,7 @@ def test_http_request_parser_two_slashes(parser) -> None:
 def test_http_request_parser_bad_method(
     parser, rfc9110_5_6_2_token_delim: bytes
 ) -> None:
-    with pytest.raises(http_exceptions.BadStatusLine):
+    with pytest.raises(http_exceptions.BadHttpMethod):
         parser.feed_data(rfc9110_5_6_2_token_delim + b'ET" /get HTTP/1.1\r\n\r\n')
 
 

tests/test_web_server.py

@@ -1,11 +1,14 @@
 import asyncio
 import socket
 from contextlib import suppress
+from typing import NoReturn
 from unittest import mock
 
 import pytest
 
 from aiohttp import client, web
+from aiohttp.http_exceptions import BadHttpMethod, BadStatusLine
+from aiohttp.pytest_plugin import AiohttpClient, AiohttpRawServer
 
 
 async def test_simple_server(aiohttp_raw_server, aiohttp_client) -> None:
@@ -56,7 +59,125 @@ async def handler(request):
     logger.exception.assert_called_with("Error handling request", exc_info=exc)
 
 
-async def test_raw_server_handler_timeout(aiohttp_raw_server, aiohttp_client) -> None:
+async def test_raw_server_logs_invalid_method_with_loop_debug(
+    aiohttp_raw_server: AiohttpRawServer,
+    aiohttp_client: AiohttpClient,
+    loop: asyncio.AbstractEventLoop,
+) -> None:
+    exc = BadHttpMethod(b"\x16\x03\x03\x01F\x01".decode(), "error")
+
+    async def handler(request: web.BaseRequest) -> NoReturn:
+        raise exc
+
+    loop = asyncio.get_event_loop()
+    loop.set_debug(True)
+    logger = mock.Mock()
+    server = await aiohttp_raw_server(handler, logger=logger)
+    cli = await aiohttp_client(server)
+    resp = await cli.get("/path/to")
+    assert resp.status == 500
+    assert resp.headers["Content-Type"].startswith("text/plain")
+
+    txt = await resp.text()
+    assert "Traceback (most recent call last):\n" in txt
+
+    # BadHttpMethod should be logged as debug
+    # 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)
+
+
+async def test_raw_server_logs_invalid_method_without_loop_debug(
+    aiohttp_raw_server: AiohttpRawServer,
+    aiohttp_client: AiohttpClient,
+    loop: asyncio.AbstractEventLoop,
+) -> None:
+    exc = BadHttpMethod(b"\x16\x03\x03\x01F\x01".decode(), "error")
+
+    async def handler(request: web.BaseRequest) -> NoReturn:
+        raise exc
+
+    loop = asyncio.get_event_loop()
+    loop.set_debug(False)
+    logger = mock.Mock()
+    server = await aiohttp_raw_server(handler, logger=logger, debug=False)
+    cli = await aiohttp_client(server)
+    resp = await cli.get("/path/to")
+    assert resp.status == 500
+    assert resp.headers["Content-Type"].startswith("text/plain")
+
+    txt = await resp.text()
+    assert "Traceback (most recent call last):\n" not in txt
+
+    # BadHttpMethod should be logged as debug
+    # 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)
+
+
+async def test_raw_server_logs_invalid_method_second_request(
+    aiohttp_raw_server: AiohttpRawServer,
+    aiohttp_client: AiohttpClient,
+    loop: asyncio.AbstractEventLoop,
+) -> None:
+    exc = BadHttpMethod(b"\x16\x03\x03\x01F\x01".decode(), "error")
+    request_count = 0
+
+    async def handler(request: web.BaseRequest) -> web.Response:
+        nonlocal request_count
+        request_count += 1
+        if request_count == 2:
+            raise exc
+        return web.Response()
+
+    loop = asyncio.get_event_loop()
+    loop.set_debug(False)
+    logger = mock.Mock()
+    server = await aiohttp_raw_server(handler, logger=logger)
+    cli = await aiohttp_client(server)
+    resp = await cli.get("/path/to")
+    assert resp.status == 200
+    resp = await cli.get("/path/to")
+    assert resp.status == 500
+    assert resp.headers["Content-Type"].startswith("text/plain")
+    # 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)
+
+
+async def test_raw_server_logs_bad_status_line_as_exception(
+    aiohttp_raw_server: AiohttpRawServer,
+    aiohttp_client: AiohttpClient,
+    loop: asyncio.AbstractEventLoop,
+) -> None:
+    exc = BadStatusLine(b"\x16\x03\x03\x01F\x01".decode(), "error")
+
+    async def handler(request: web.BaseRequest) -> NoReturn:
+        raise exc
+
+    loop = asyncio.get_event_loop()
+    loop.set_debug(False)
+    logger = mock.Mock()
+    server = await aiohttp_raw_server(handler, logger=logger, debug=False)
+    cli = await aiohttp_client(server)
+    resp = await cli.get("/path/to")
+    assert resp.status == 500
+    assert resp.headers["Content-Type"].startswith("text/plain")
+
+    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)
+
+
+async def test_raw_server_handler_timeout(
+    aiohttp_raw_server: AiohttpRawServer, aiohttp_client: AiohttpClient
+) -> None:
+    loop = asyncio.get_event_loop()
+    loop.set_debug(True)
     exc = asyncio.TimeoutError("error")
 
     async def handler(request):