From 1c076de5873f37d052563af52ce90e4c00a02588 Mon Sep 17 00:00:00 2001 From: Tom Christie Date: Fri, 6 Jan 2023 10:41:42 +0000 Subject: [PATCH 1/4] Add DEBUG level logging --- httpcore/_trace.py | 45 +++++++++++++++---- httpcore/backends/mock.py | 6 +++ tests/_async/test_connection_pool.py | 67 ++++++++++++++++++++++++++++ tests/_sync/test_connection_pool.py | 67 ++++++++++++++++++++++++++++ 4 files changed, 177 insertions(+), 8 deletions(-) diff --git a/httpcore/_trace.py b/httpcore/_trace.py index d98325f2..ecb67b02 100644 --- a/httpcore/_trace.py +++ b/httpcore/_trace.py @@ -1,20 +1,37 @@ +import logging from types import TracebackType from typing import Any, Dict, Optional, Type from ._models import Request +logger = logging.getLogger("httpcore") + class Trace: def __init__( self, name: str, request: Request, kwargs: Optional[Dict[str, Any]] = None ) -> None: self.name = name - self.trace = request.extensions.get("trace") + self.trace_extension = request.extensions.get("trace") + self.debug = logger.isEnabledFor(logging.DEBUG) self.kwargs = kwargs or {} self.return_value: Any = None + self.should_trace = self.debug or self.trace_extension is not None + + def trace(self, name: str, info: Dict[str, Any]) -> None: + if self.trace_extension is not None: + self.trace_extension(name, info) + + if self.debug: + if not info or "return_value" in info and info["return_value"] is None: + message = name + else: + args = " ".join([f"{key}={value!r}" for key, value in info.items()]) + message = f"{name} {args}" + logger.debug(message) def __enter__(self) -> "Trace": - if self.trace is not None: + if self.should_trace: info = self.kwargs self.trace(f"{self.name}.started", info) return self @@ -25,7 +42,7 @@ def __exit__( exc_value: Optional[BaseException] = None, traceback: Optional[TracebackType] = None, ) -> None: - if self.trace is not None: + if self.should_trace: if exc_value is None: info = {"return_value": self.return_value} self.trace(f"{self.name}.complete", info) @@ -33,10 +50,22 @@ def __exit__( info = {"exception": exc_value} self.trace(f"{self.name}.failed", info) + async def atrace(self, name: str, info: Dict[str, Any]) -> None: + if self.trace_extension is not None: + await self.trace_extension(name, info) + + if self.debug: + if not info or "return_value" in info and info["return_value"] is None: + message = name + else: + args = " ".join([f"{key}={value!r}" for key, value in info.items()]) + message = f"{name} {args}" + logger.debug(message) + async def __aenter__(self) -> "Trace": - if self.trace is not None: + if self.should_trace: info = self.kwargs - await self.trace(f"{self.name}.started", info) + await self.atrace(f"{self.name}.started", info) return self async def __aexit__( @@ -45,10 +74,10 @@ async def __aexit__( exc_value: Optional[BaseException] = None, traceback: Optional[TracebackType] = None, ) -> None: - if self.trace is not None: + if self.should_trace: if exc_value is None: info = {"return_value": self.return_value} - await self.trace(f"{self.name}.complete", info) + await self.atrace(f"{self.name}.complete", info) else: info = {"exception": exc_value} - await self.trace(f"{self.name}.failed", info) + await self.atrace(f"{self.name}.failed", info) diff --git a/httpcore/backends/mock.py b/httpcore/backends/mock.py index 9aba0ead..0dab4eea 100644 --- a/httpcore/backends/mock.py +++ b/httpcore/backends/mock.py @@ -44,6 +44,9 @@ def start_tls( def get_extra_info(self, info: str) -> typing.Any: return MockSSLObject(http2=self._http2) if info == "ssl_object" else None + def __repr__(self) -> str: + return "" + class MockBackend(NetworkBackend): def __init__(self, buffer: typing.List[bytes], http2: bool = False) -> None: @@ -98,6 +101,9 @@ async def start_tls( def get_extra_info(self, info: str) -> typing.Any: return MockSSLObject(http2=self._http2) if info == "ssl_object" else None + def __repr__(self) -> str: + return "" + class AsyncMockBackend(AsyncNetworkBackend): def __init__(self, buffer: typing.List[bytes], http2: bool = False) -> None: diff --git a/tests/_async/test_connection_pool.py b/tests/_async/test_connection_pool.py index d2ac58a4..98f007e5 100644 --- a/tests/_async/test_connection_pool.py +++ b/tests/_async/test_connection_pool.py @@ -1,3 +1,4 @@ +import logging from typing import List, Optional import pytest @@ -160,6 +161,72 @@ async def trace(name, kwargs): ] +@pytest.mark.anyio +async def test_debug_request(caplog): + """ + The 'trace' request extension allows for a callback function to inspect the + internal events that occur while sending a request. + """ + caplog.set_level(logging.DEBUG) + + network_backend = AsyncMockBackend( + [ + b"HTTP/1.1 200 OK\r\n", + b"Content-Type: plain/text\r\n", + b"Content-Length: 13\r\n", + b"\r\n", + b"Hello, world!", + ] + ) + + async with AsyncConnectionPool(network_backend=network_backend) as pool: + await pool.request("GET", "http://example.com/") + + assert caplog.record_tuples == [ + ( + "httpcore", + logging.DEBUG, + "connection.connect_tcp.started host='example.com' port=80 local_address=None timeout=None", + ), + ( + "httpcore", + logging.DEBUG, + "connection.connect_tcp.complete return_value=", + ), + ( + "httpcore", + logging.DEBUG, + "http11.send_request_headers.started request=", + ), + ("httpcore", logging.DEBUG, "http11.send_request_headers.complete"), + ( + "httpcore", + logging.DEBUG, + "http11.send_request_body.started request=", + ), + ("httpcore", logging.DEBUG, "http11.send_request_body.complete"), + ( + "httpcore", + logging.DEBUG, + "http11.receive_response_headers.started request=", + ), + ( + "httpcore", + logging.DEBUG, + "http11.receive_response_headers.complete return_value=" + "(b'HTTP/1.1', 200, b'OK', [(b'Content-Type', b'plain/text'), (b'Content-Length', b'13')])", + ), + ( + "httpcore", + logging.DEBUG, + "http11.receive_response_body.started request=", + ), + ("httpcore", logging.DEBUG, "http11.receive_response_body.complete"), + ("httpcore", logging.DEBUG, "http11.response_closed.started"), + ("httpcore", logging.DEBUG, "http11.response_closed.complete"), + ] + + @pytest.mark.anyio async def test_connection_pool_with_http_exception(): """ diff --git a/tests/_sync/test_connection_pool.py b/tests/_sync/test_connection_pool.py index 453b7fdc..dda86b0e 100644 --- a/tests/_sync/test_connection_pool.py +++ b/tests/_sync/test_connection_pool.py @@ -1,3 +1,4 @@ +import logging from typing import List, Optional import pytest @@ -161,6 +162,72 @@ def trace(name, kwargs): +def test_debug_request(caplog): + """ + The 'trace' request extension allows for a callback function to inspect the + internal events that occur while sending a request. + """ + caplog.set_level(logging.DEBUG) + + network_backend = MockBackend( + [ + b"HTTP/1.1 200 OK\r\n", + b"Content-Type: plain/text\r\n", + b"Content-Length: 13\r\n", + b"\r\n", + b"Hello, world!", + ] + ) + + with ConnectionPool(network_backend=network_backend) as pool: + pool.request("GET", "http://example.com/") + + assert caplog.record_tuples == [ + ( + "httpcore", + logging.DEBUG, + "connection.connect_tcp.started host='example.com' port=80 local_address=None timeout=None", + ), + ( + "httpcore", + logging.DEBUG, + "connection.connect_tcp.complete return_value=", + ), + ( + "httpcore", + logging.DEBUG, + "http11.send_request_headers.started request=", + ), + ("httpcore", logging.DEBUG, "http11.send_request_headers.complete"), + ( + "httpcore", + logging.DEBUG, + "http11.send_request_body.started request=", + ), + ("httpcore", logging.DEBUG, "http11.send_request_body.complete"), + ( + "httpcore", + logging.DEBUG, + "http11.receive_response_headers.started request=", + ), + ( + "httpcore", + logging.DEBUG, + "http11.receive_response_headers.complete return_value=" + "(b'HTTP/1.1', 200, b'OK', [(b'Content-Type', b'plain/text'), (b'Content-Length', b'13')])", + ), + ( + "httpcore", + logging.DEBUG, + "http11.receive_response_body.started request=", + ), + ("httpcore", logging.DEBUG, "http11.receive_response_body.complete"), + ("httpcore", logging.DEBUG, "http11.response_closed.started"), + ("httpcore", logging.DEBUG, "http11.response_closed.complete"), + ] + + + def test_connection_pool_with_http_exception(): """ HTTP/1.1 requests that result in an exception during the connection should From afbfa83f8f5244be39f3fd4b8982e05f6080162c Mon Sep 17 00:00:00 2001 From: Tom Christie Date: Mon, 9 Jan 2023 14:44:22 +0000 Subject: [PATCH 2/4] Add connection.close logging --- httpcore/_async/connection.py | 3 ++- httpcore/_sync/connection.py | 3 ++- httpcore/_trace.py | 9 +++++++-- 3 files changed, 11 insertions(+), 4 deletions(-) diff --git a/httpcore/_async/connection.py b/httpcore/_async/connection.py index b9196781..18444c3f 100644 --- a/httpcore/_async/connection.py +++ b/httpcore/_async/connection.py @@ -156,7 +156,8 @@ def can_handle_request(self, origin: Origin) -> bool: async def aclose(self) -> None: if self._connection is not None: - await self._connection.aclose() + async with Trace("connection.close", None, {}): + await self._connection.aclose() def is_available(self) -> bool: if self._connection is None: diff --git a/httpcore/_sync/connection.py b/httpcore/_sync/connection.py index 3312c2c8..9c703498 100644 --- a/httpcore/_sync/connection.py +++ b/httpcore/_sync/connection.py @@ -156,7 +156,8 @@ def can_handle_request(self, origin: Origin) -> bool: def close(self) -> None: if self._connection is not None: - self._connection.close() + with Trace("connection.close", None, {}): + self._connection.close() def is_available(self) -> bool: if self._connection is None: diff --git a/httpcore/_trace.py b/httpcore/_trace.py index ecb67b02..62ca59e4 100644 --- a/httpcore/_trace.py +++ b/httpcore/_trace.py @@ -9,10 +9,15 @@ class Trace: def __init__( - self, name: str, request: Request, kwargs: Optional[Dict[str, Any]] = None + self, + name: str, + request: Optional[Request] = None, + kwargs: Optional[Dict[str, Any]] = None, ) -> None: self.name = name - self.trace_extension = request.extensions.get("trace") + self.trace_extension = ( + None if request is None else request.extensions.get("trace") + ) self.debug = logger.isEnabledFor(logging.DEBUG) self.kwargs = kwargs or {} self.return_value: Any = None From 98cd8f9870c4ecf7d30bfae6afc11046a0f6b83f Mon Sep 17 00:00:00 2001 From: Tom Christie Date: Mon, 16 Jan 2023 11:47:31 +0000 Subject: [PATCH 3/4] Update tests --- tests/_async/test_connection_pool.py | 2 ++ tests/_sync/test_connection_pool.py | 2 ++ 2 files changed, 4 insertions(+) diff --git a/tests/_async/test_connection_pool.py b/tests/_async/test_connection_pool.py index 98f007e5..c2c49e0d 100644 --- a/tests/_async/test_connection_pool.py +++ b/tests/_async/test_connection_pool.py @@ -224,6 +224,8 @@ async def test_debug_request(caplog): ("httpcore", logging.DEBUG, "http11.receive_response_body.complete"), ("httpcore", logging.DEBUG, "http11.response_closed.started"), ("httpcore", logging.DEBUG, "http11.response_closed.complete"), + ("httpcore", logging.DEBUG, "connection.close.started"), + ("httpcore", logging.DEBUG, "connection.close.complete"), ] diff --git a/tests/_sync/test_connection_pool.py b/tests/_sync/test_connection_pool.py index dda86b0e..59d94774 100644 --- a/tests/_sync/test_connection_pool.py +++ b/tests/_sync/test_connection_pool.py @@ -224,6 +224,8 @@ def test_debug_request(caplog): ("httpcore", logging.DEBUG, "http11.receive_response_body.complete"), ("httpcore", logging.DEBUG, "http11.response_closed.started"), ("httpcore", logging.DEBUG, "http11.response_closed.complete"), + ("httpcore", logging.DEBUG, "connection.close.started"), + ("httpcore", logging.DEBUG, "connection.close.complete"), ] From 238f0dafe0c75831da19d5f2bdb4063963ef7ce0 Mon Sep 17 00:00:00 2001 From: Tom Christie Date: Thu, 16 Mar 2023 10:33:51 +0000 Subject: [PATCH 4/4] Add logging documentation --- docs/logging.md | 41 +++++++++++++++++++++++++++++++++++++++++ mkdocs.yml | 1 + 2 files changed, 42 insertions(+) create mode 100644 docs/logging.md diff --git a/docs/logging.md b/docs/logging.md new file mode 100644 index 00000000..670448df --- /dev/null +++ b/docs/logging.md @@ -0,0 +1,41 @@ +# Logging + +If you need to inspect the internal behaviour of `httpcore`, you can use Python's standard logging to output debug level information. + +For example, the following configuration... + +```python +import logging +import httpcore + +logging.basicConfig( + format="%(levelname)s [%(asctime)s] %(name)s - %(message)s", + datefmt="%Y-%m-%d %H:%M:%S", + level=logging.DEBUG +) + +httpcore.request('GET', 'https://www.example.com') +``` + +Will send debug level output to the console, or wherever `stdout` is directed too... + +``` +DEBUG [2023-01-09 14:44:00] httpcore - connection.connect_tcp.started host='www.example.com' port=443 local_address=None timeout=None +DEBUG [2023-01-09 14:44:00] httpcore - connection.connect_tcp.complete return_value= +DEBUG [2023-01-09 14:44:00] httpcore - connection.start_tls.started ssl_context= server_hostname='www.example.com' timeout=None +DEBUG [2023-01-09 14:44:00] httpcore - connection.start_tls.complete return_value= +DEBUG [2023-01-09 14:44:00] httpcore - http11.send_request_headers.started request= +DEBUG [2023-01-09 14:44:00] httpcore - http11.send_request_headers.complete +DEBUG [2023-01-09 14:44:00] httpcore - http11.send_request_body.started request= +DEBUG [2023-01-09 14:44:00] httpcore - http11.send_request_body.complete +DEBUG [2023-01-09 14:44:00] httpcore - http11.receive_response_headers.started request= +DEBUG [2023-01-09 14:44:00] httpcore - http11.receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Age', b'572646'), (b'Cache-Control', b'max-age=604800'), (b'Content-Type', b'text/html; charset=UTF-8'), (b'Date', b'Mon, 09 Jan 2023 14:44:00 GMT'), (b'Etag', b'"3147526947+ident"'), (b'Expires', b'Mon, 16 Jan 2023 14:44:00 GMT'), (b'Last-Modified', b'Thu, 17 Oct 2019 07:18:26 GMT'), (b'Server', b'ECS (nyb/1D18)'), (b'Vary', b'Accept-Encoding'), (b'X-Cache', b'HIT'), (b'Content-Length', b'1256')]) +DEBUG [2023-01-09 14:44:00] httpcore - http11.receive_response_body.started request= +DEBUG [2023-01-09 14:44:00] httpcore - http11.receive_response_body.complete +DEBUG [2023-01-09 14:44:00] httpcore - http11.response_closed.started +DEBUG [2023-01-09 14:44:00] httpcore - http11.response_closed.complete +DEBUG [2023-01-09 14:44:00] httpcore - connection.close.started +DEBUG [2023-01-09 14:44:00] httpcore - connection.close.complete +``` + +The exact formatting of the debug logging may be subject to change across different versions of `httpcore`. If you need to rely on a particular format it is recommended that you pin installation of the package to a fixed version. \ No newline at end of file diff --git a/mkdocs.yml b/mkdocs.yml index bd3e933f..8fd57903 100644 --- a/mkdocs.yml +++ b/mkdocs.yml @@ -13,6 +13,7 @@ nav: - HTTP/2: 'http2.md' - Async Support: 'async.md' - Extensions: 'extensions.md' + - Logging: 'logging.md' - Exceptions: 'exceptions.md' theme: