Add easier debug logging for users (#277)

Co-Authored-By: Florimond Manca <florimond.manca@gmail.com>

Author: sethmlarson

docs/environment_variables.md

@@ -0,0 +1,46 @@
+Environment Variables
+=====================
+
+The HTTPX library can be configured via environment variables.
+Here is a list of environment variables that HTTPX recognizes
+and what function they serve:
+
+`HTTPX_DEBUG`
+-----------
+
+Valid values: `1`, `true`
+
+If this environment variable is set to a valid value then low-level
+details about the execution of HTTP requests will be logged to `stderr`.
+
+This can help you debug issues and see what's exactly being sent
+over the wire and to which location.
+
+Example:
+
+```python
+# test_script.py
+
+import httpx
+client = httpx.Client()
+client.get("https://google.com")
+```
+
+```console
+user@host:~$ HTTPX_DEBUG=1 python test_script.py
+20:54:17.585 - httpx.dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='www.google.com' port=443)
+20:54:17.585 - httpx.dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
+20:54:17.590 - httpx.dispatch.connection - start_connect host='www.google.com' port=443 timeout=TimeoutConfig(timeout=5.0)
+20:54:17.651 - httpx.dispatch.connection - connected http_version='HTTP/2'
+20:54:17.651 - httpx.dispatch.http2 - send_headers stream_id=1 headers=[(b':method', b'GET'), (b':authority', b'www.google.com'), ...]
+20:54:17.652 - httpx.dispatch.http2 - end_stream stream_id=1
+20:54:17.681 - httpx.dispatch.http2 - receive_event stream_id=0 event=<RemoteSettingsChanged changed_settings:{...}>
+20:54:17.681 - httpx.dispatch.http2 - receive_event stream_id=0 event=<WindowUpdated stream_id:0, delta:983041>
+20:54:17.682 - httpx.dispatch.http2 - receive_event stream_id=0 event=<SettingsAcknowledged changed_settings:{}>
+20:54:17.739 - httpx.dispatch.http2 - receive_event stream_id=1 event=<ResponseReceived stream_id:1, headers:[(b':status', b'200'), ...]>
+20:54:17.741 - httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:5224 data:>
+20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:59, data:>
+20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=1 event=<StreamEnded stream_id:1>
+20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=0 event=<PingReceived ping_data:0000000000000000>
+20:54:17.743 - httpx.dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
+```

httpx/dispatch/connection.py

@@ -15,6 +15,7 @@
     VerifyTypes,
 )
 from ..models import AsyncRequest, AsyncResponse, Origin
+from ..utils import get_logger
 from .base import AsyncDispatcher
 from .http2 import HTTP2Connection
 from .http11 import HTTP11Connection
@@ -23,6 +24,9 @@
 ReleaseCallback = typing.Callable[["HTTPConnection"], typing.Awaitable[None]]
 
 
+logger = get_logger(__name__)
+
+
 class HTTPConnection(AsyncDispatcher):
     def __init__(
         self,
@@ -79,8 +83,10 @@ async def connect(
         else:
             on_release = functools.partial(self.release_func, self)
 
+        logger.debug(f"start_connect host={host!r} port={port!r} timeout={timeout!r}")
         stream = await self.backend.connect(host, port, ssl_context, timeout)
         http_version = stream.get_http_version()
+        logger.debug(f"connected http_version={http_version!r}")
 
         if http_version == "HTTP/2":
             self.h2_connection = HTTP2Connection(
@@ -102,6 +108,7 @@ async def get_ssl_context(self, ssl: SSLConfig) -> typing.Optional[ssl.SSLContex
         )
 
     async def close(self) -> None:
+        logger.debug("close_connection")
         if self.h2_connection is not None:
             await self.h2_connection.close()
         elif self.h11_connection is not None:
@@ -125,3 +132,7 @@ def is_connection_dropped(self) -> bool:
         else:
             assert self.h11_connection is not None
             return self.h11_connection.is_connection_dropped()
+
+    def __repr__(self) -> str:
+        class_name = self.__class__.__name__
+        return f"{class_name}(origin={self.origin!r})"

httpx/dispatch/connection_pool.py

@@ -12,12 +12,16 @@
     VerifyTypes,
 )
 from ..models import AsyncRequest, AsyncResponse, Origin
+from ..utils import get_logger
 from .base import AsyncDispatcher
 from .connection import HTTPConnection
 
 CONNECTIONS_DICT = typing.Dict[Origin, typing.List[HTTPConnection]]
 
 
+logger = get_logger(__name__)
+
+
 class ConnectionStore:
     """
     We need to maintain collections of connections in a way that allows us to:
@@ -122,6 +126,7 @@ async def send(
         return response
 
     async def acquire_connection(self, origin: Origin) -> HTTPConnection:
+        logger.debug(f"acquire_connection origin={origin!r}")
         connection = self.active_connections.pop_by_origin(origin, http2_only=True)
         if connection is None:
             connection = self.keepalive_connections.pop_by_origin(origin)
@@ -141,12 +146,16 @@ async def acquire_connection(self, origin: Origin) -> HTTPConnection:
                 backend=self.backend,
                 release_func=self.release_connection,
             )
+            logger.debug(f"new_connection connection={connection!r}")
+        else:
+            logger.debug(f"reuse_connection connection={connection!r}")
 
         self.active_connections.add(connection)
 
         return connection
 
     async def release_connection(self, connection: HTTPConnection) -> None:
+        logger.debug(f"release_connection connection={connection!r}")
         if connection.is_closed:
             self.active_connections.remove(connection)
             self.max_connections.release()

httpx/dispatch/http11.py

@@ -5,6 +5,7 @@
 from ..concurrency.base import BaseStream, ConcurrencyBackend, TimeoutFlag
 from ..config import TimeoutConfig, TimeoutTypes
 from ..models import AsyncRequest, AsyncResponse
+from ..utils import get_logger
 
 H11Event = typing.Union[
     h11.Request,
@@ -22,6 +23,9 @@
 OnReleaseCallback = typing.Callable[[], typing.Awaitable[None]]
 
 
+logger = get_logger(__name__)
+
+
 class HTTP11Connection:
     READ_NUM_BYTES = 4096
 
@@ -61,6 +65,7 @@ async def send(
     async def close(self) -> None:
         event = h11.ConnectionClosed()
         try:
+            logger.debug(f"send_event event={event!r}")
             self.h11_state.send(event)
         except h11.LocalProtocolError:  # pragma: no cover
             # Premature client disconnect
@@ -73,6 +78,12 @@ async def _send_request(
         """
         Send the request method, URL, and headers to the network.
         """
+        logger.debug(
+            f"send_headers method={request.method!r} "
+            f"target={request.url.full_path!r} "
+            f"headers={request.headers!r}"
+        )
+
         method = request.method.encode("ascii")
         target = request.url.full_path.encode("ascii")
         headers = request.headers.raw
@@ -88,6 +99,7 @@ async def _send_request_data(
         try:
             # Send the request body.
             async for chunk in data:
+                logger.debug(f"send_data data=Data(<{len(chunk)} bytes>)")
                 event = h11.Data(data=chunk)
                 await self._send_event(event, timeout)
 
@@ -150,6 +162,12 @@ async def _receive_event(self, timeout: TimeoutConfig = None) -> H11Event:
         """
         while True:
             event = self.h11_state.next_event()
+
+            if isinstance(event, h11.Data):
+                logger.debug(f"receive_event event=Data(<{len(event.data)} bytes>)")
+            else:
+                logger.debug(f"receive_event event={event!r}")
+
             if event is h11.NEED_DATA:
                 try:
                     data = await self.stream.read(
@@ -164,6 +182,11 @@ async def _receive_event(self, timeout: TimeoutConfig = None) -> H11Event:
         return event
 
     async def response_closed(self) -> None:
+        logger.debug(
+            f"response_closed "
+            f"our_state={self.h11_state.our_state!r} "
+            f"their_state={self.h11_state.their_state}"
+        )
         if (
             self.h11_state.our_state is h11.DONE
             and self.h11_state.their_state is h11.DONE

httpx/dispatch/http2.py

@@ -7,6 +7,9 @@
 from ..concurrency.base import BaseStream, ConcurrencyBackend, TimeoutFlag
 from ..config import TimeoutConfig, TimeoutTypes
 from ..models import AsyncRequest, AsyncResponse
+from ..utils import get_logger
+
+logger = get_logger(__name__)
 
 
 class HTTP2Connection:
@@ -74,6 +77,15 @@ async def send_headers(
             (b":scheme", request.url.scheme.encode("ascii")),
             (b":path", request.url.full_path.encode("ascii")),
         ] + [(k, v) for k, v in request.headers.raw if k != b"host"]
+
+        logger.debug(
+            f"send_headers "
+            f"stream_id={stream_id} "
+            f"method={request.method!r} "
+            f"target={request.url.full_path!r} "
+            f"headers={headers!r}"
+        )
+
         self.h2_state.send_headers(stream_id, headers)
         data_to_send = self.h2_state.data_to_send()
         await self.stream.write(data_to_send, timeout)
@@ -100,11 +112,17 @@ async def send_data(
         chunk_size = min(len(data), flow_control)
         for idx in range(0, len(data), chunk_size):
             chunk = data[idx : idx + chunk_size]
+
+            logger.debug(
+                f"send_data stream_id={stream_id} data=Data(<{len(chunk)} bytes>)"
+            )
+
             self.h2_state.send_data(stream_id, chunk)
             data_to_send = self.h2_state.data_to_send()
             await self.stream.write(data_to_send, timeout)
 
     async def end_stream(self, stream_id: int, timeout: TimeoutConfig = None) -> None:
+        logger.debug(f"end_stream stream_id={stream_id}")
         self.h2_state.end_stream(stream_id)
         data_to_send = self.h2_state.data_to_send()
         await self.stream.write(data_to_send, timeout)
@@ -151,7 +169,11 @@ async def receive_event(
             data = await self.stream.read(self.READ_NUM_BYTES, timeout, flag=flag)
             events = self.h2_state.receive_data(data)
             for event in events:
-                if getattr(event, "stream_id", 0):
+                event_stream_id = getattr(event, "stream_id", 0)
+                logger.debug(
+                    f"receive_event stream_id={event_stream_id} event={event!r}"
+                )
+                if event_stream_id:
                     self.events[event.stream_id].append(event)
 
             data_to_send = self.h2_state.data_to_send()

httpx/models.py

@@ -243,6 +243,12 @@ def __eq__(self, other: typing.Any) -> bool:
     def __hash__(self) -> int:
         return hash((self.scheme, self.host, self.port))
 
+    def __repr__(self) -> str:
+        class_name = self.__class__.__name__
+        return (
+            f"{class_name}(scheme={self.scheme!r} host={self.host!r} port={self.port})"
+        )
+
 
 class QueryParams(typing.Mapping[str, str]):
     """

httpx/utils.py

@@ -1,7 +1,9 @@
 import codecs
+import logging
 import netrc
 import os
 import re
+import sys
 import typing
 from pathlib import Path
 
@@ -140,3 +142,30 @@ def parse_header_links(value: str) -> typing.List[typing.Dict[str, str]]:
             link[key.strip(replace_chars)] = value.strip(replace_chars)
         links.append(link)
     return links
+
+
+_LOGGER_INITIALIZED = False
+
+
+def get_logger(name: str) -> logging.Logger:
+    """Gets a `logging.Logger` instance and optionally
+    sets up debug logging if the user requests it via
+    the `HTTPX_DEBUG=1` environment variable.
+    """
+    global _LOGGER_INITIALIZED
+
+    if not _LOGGER_INITIALIZED:
+        _LOGGER_INITIALIZED = True
+        if os.environ.get("HTTPX_DEBUG", "").lower() in ("1", "true"):
+            logger = logging.getLogger("httpx")
+            logger.setLevel(logging.DEBUG)
+            handler = logging.StreamHandler(sys.stderr)
+            handler.setFormatter(
+                logging.Formatter(
+                    fmt="%(asctime)s.%(msecs)03d - %(name)s - %(message)s",
+                    datefmt="%H:%M:%S",
+                )
+            )
+            logger.addHandler(handler)
+
+    return logging.getLogger(name)

mkdocs.yml

@@ -12,6 +12,7 @@ nav:
     - Introduction: 'index.md'
     - QuickStart: 'quickstart.md'
     - Advanced Usage: 'advanced.md'
+    - Environment Variables: 'environment_variables.md'
     - Parallel Requests: 'parallel.md'
     - Async Client: 'async.md'
     - Requests Compatibility: 'compatibility.md'

tests/test_utils.py

@@ -1,7 +1,10 @@
+import logging
 import os
 
 import pytest
 
+import httpx
+from httpx import utils
 from httpx.utils import get_netrc_login, guess_json_utf, parse_header_links
 
 
@@ -87,3 +90,24 @@ def test_get_netrc_login():
 )
 def test_parse_header_links(value, expected):
     assert parse_header_links(value) == expected
+
+
+@pytest.mark.asyncio
+@pytest.mark.parametrize("httpx_debug", ["0", "1", "True", "False"])
+async def test_httpx_debug_enabled_stderr_logging(server, capsys, httpx_debug):
+    os.environ["HTTPX_DEBUG"] = httpx_debug
+
+    # Force a reload on the logging handlers
+    utils._LOGGER_INITIALIZED = False
+    utils.get_logger("httpx")
+
+    async with httpx.AsyncClient() as client:
+        await client.get("http://127.0.0.1:8000/")
+
+    if httpx_debug in ("1", "True"):
+        assert "httpx.dispatch.connection_pool" in capsys.readouterr().err
+    else:
+        assert "httpx.dispatch.connection_pool" not in capsys.readouterr().err
+
+    # Reset the logger so we don't have verbose output in all unit tests
+    logging.getLogger("httpx").handlers = []