Add DEBUG level logging. (#648)

* Add DEBUG level logging * Add connection.close logging * Update tests * Add logging documentation
encode · Mar 16, 2023 · 4af5e1c · 4af5e1c
1 parent a174e66
commit 4af5e1c
Show file tree

Hide file tree

Showing 8 changed files with 233 additions and 11 deletions.
diff --git a/docs/logging.md 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=<httpcore.backends.sync.SyncStream object at 0x109ba6610>
+DEBUG [2023-01-09 14:44:00] httpcore - connection.start_tls.started ssl_context=<ssl.SSLContext object at 0x109e427b0> server_hostname='www.example.com' timeout=None
+DEBUG [2023-01-09 14:44:00] httpcore - connection.start_tls.complete return_value=<httpcore.backends.sync.SyncStream object at 0x109e8b050>
+DEBUG [2023-01-09 14:44:00] httpcore - http11.send_request_headers.started request=<Request [b'GET']>
+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=<Request [b'GET']>
+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=<Request [b'GET']>
+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=<Request [b'GET']>
+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.
diff --git 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
@@ -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
@@ -1,20 +1,42 @@
+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
+        self,
+        name: str,
+        request: Optional[Request] = None,
+        kwargs: Optional[Dict[str, Any]] = None,
     ) -> None:
         self.name = name
-        self.trace = 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
+        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,18 +47,30 @@ 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)
             else:
                 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 +79,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
@@ -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 "<httpcore.MockStream>"
+
 
 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 "<httpcore.AsyncMockStream>"
+
 
 class AsyncMockBackend(AsyncNetworkBackend):
     def __init__(self, buffer: typing.List[bytes], http2: bool = False) -> None:

diff --git 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:

diff --git 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,74 @@ 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.AsyncMockStream>",
+        ),
+        (
+            "httpcore",
+            logging.DEBUG,
+            "http11.send_request_headers.started request=<Request [b'GET']>",
+        ),
+        ("httpcore", logging.DEBUG, "http11.send_request_headers.complete"),
+        (
+            "httpcore",
+            logging.DEBUG,
+            "http11.send_request_body.started request=<Request [b'GET']>",
+        ),
+        ("httpcore", logging.DEBUG, "http11.send_request_body.complete"),
+        (
+            "httpcore",
+            logging.DEBUG,
+            "http11.receive_response_headers.started request=<Request [b'GET']>",
+        ),
+        (
+            "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=<Request [b'GET']>",
+        ),
+        ("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"),
+    ]
+
+
 @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
@@ -1,3 +1,4 @@
+import logging
 from typing import List, Optional
 
 import pytest
@@ -161,6 +162,74 @@ 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.MockStream>",
+        ),
+        (
+            "httpcore",
+            logging.DEBUG,
+            "http11.send_request_headers.started request=<Request [b'GET']>",
+        ),
+        ("httpcore", logging.DEBUG, "http11.send_request_headers.complete"),
+        (
+            "httpcore",
+            logging.DEBUG,
+            "http11.send_request_body.started request=<Request [b'GET']>",
+        ),
+        ("httpcore", logging.DEBUG, "http11.send_request_body.complete"),
+        (
+            "httpcore",
+            logging.DEBUG,
+            "http11.receive_response_headers.started request=<Request [b'GET']>",
+        ),
+        (
+            "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=<Request [b'GET']>",
+        ),
+        ("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"),
+    ]
+
+
+
 def test_connection_pool_with_http_exception():
     """
     HTTP/1.1 requests that result in an exception during the connection should