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 dd317edaf79..988e4247f93 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 c43ee0d9659..b8dda999acf 100644 --- a/aiohttp/http_exceptions.py +++ b/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 diff --git a/aiohttp/http_parser.py b/aiohttp/http_parser.py index 148a30b2ca1..1b8b5b4d49e 100644 --- a/aiohttp/http_parser.py +++ b/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) diff --git a/aiohttp/web_protocol.py b/aiohttp/web_protocol.py index 2201eef30ad..fe2ae8a1269 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 @@ -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: diff --git a/tests/test_http_parser.py b/tests/test_http_parser.py index a8305da84f7..58fef625f82 100644 --- a/tests/test_http_parser.py +++ b/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') diff --git a/tests/test_web_server.py b/tests/test_web_server.py index 9e2d078c1a0..e77df623020 100644 --- a/tests/test_web_server.py +++ b/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):