From c11fe96f9831f5ab3e4042ce3040424dfc2e4a0d Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Wed, 27 Nov 2024 08:35:00 -0800 Subject: [PATCH] Downgrade logging of invalid HTTP methods on first request to debug level (#10055) --- CHANGES/10055.misc.rst | 3 + aiohttp/_http_parser.pyx | 4 +- aiohttp/http_exceptions.py | 7 +++ aiohttp/http_parser.py | 5 +- aiohttp/web_protocol.py | 14 ++++- tests/test_http_parser.py | 2 +- tests/test_web_server.py | 115 +++++++++++++++++++++++++++++++++++++ 7 files changed, 145 insertions(+), 5 deletions(-) create mode 100644 CHANGES/10055.misc.rst diff --git a/CHANGES/10055.misc.rst b/CHANGES/10055.misc.rst new file mode 100644 index 00000000000..3a5fa074f77 --- /dev/null +++ b/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. diff --git a/aiohttp/_http_parser.pyx b/aiohttp/_http_parser.pyx index 30767dae6ce..34b8785a5e1 100644 --- a/aiohttp/_http_parser.pyx +++ b/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: diff --git a/aiohttp/http_exceptions.py b/aiohttp/http_exceptions.py index 38839e48f6e..2b6d50cf980 100644 --- a/aiohttp/http_exceptions.py +++ b/aiohttp/http_exceptions.py @@ -97,5 +97,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 diff --git a/aiohttp/http_parser.py b/aiohttp/http_parser.py index 59f69a12a1a..d44f4cb12f1 100644 --- a/aiohttp/http_parser.py +++ b/aiohttp/http_parser.py @@ -38,6 +38,7 @@ ) from .http_exceptions import ( BadHttpMessage, + BadHttpMethod, BadStatusLine, ContentEncodingError, ContentLengthError, @@ -564,7 +565,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( @@ -573,7 +574,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) diff --git a/aiohttp/web_protocol.py b/aiohttp/web_protocol.py index 1f24e8bcece..d83c289a40b 100644 --- a/aiohttp/web_protocol.py +++ b/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 @@ -712,7 +713,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: diff --git a/tests/test_http_parser.py b/tests/test_http_parser.py index 3c9b6067cc5..f7489bc7656 100644 --- a/tests/test_http_parser.py +++ b/tests/test_http_parser.py @@ -988,7 +988,7 @@ def test_http_request_parser_two_slashes(parser: HttpRequestParser) -> None: def test_http_request_parser_bad_method( parser: HttpRequestParser, 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') diff --git a/tests/test_web_server.py b/tests/test_web_server.py index 30704601aa1..07d6c420f32 100644 --- a/tests/test_web_server.py +++ b/tests/test_web_server.py @@ -7,6 +7,7 @@ import pytest from aiohttp import client, web +from aiohttp.http_exceptions import BadHttpMethod, BadStatusLine from aiohttp.pytest_plugin import AiohttpClient, AiohttpRawServer @@ -69,6 +70,120 @@ async def handler(request: web.BaseRequest) -> NoReturn: logger.exception.assert_called_with("Error handling request", exc_info=exc) +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) + 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) + 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: