Repository: encode/httpx
Pull request: Add easier debug logging for users
This builds on #240 and adds it to all request-making dispatchers. It can be added to ASGI and WSGI dispatchers as well but I'm less familiar with what information would be useful for debugging those use-cases.

This also adds a new environment variable `HTTPX_DEBUG` which can be turned on to automatically display these debug logs.

A new section `Environment Variables` has been added to the documentation with the intent of future expansion for all environment variables that HTTPX will react to.

Closes #221.

Problem statement:
Add DEBUG logging to Dispatchers and Client for easier debugging
I was finding it difficult to debug some low-level behaviors when connecting to a specific host due to some HTTP/2-specific events. I'm sure our users will feel the same way when using HTTPX if something's not working.

Hints from issue discussion:
💯 Yes please!

Commit message: Add easier debug logging for users

Patch to review:
diff --git a/docs/environment_variables.md b/docs/environment_variables.md
new file mode 100644
index 0000000000..bb55151461
--- /dev/null
+++ b/docs/environment_variables.md
@@ -0,0 +1,47 @@
+Environment Variables
+=====================
+
+The HTTPX library can be configured via environment variables.
+Here are 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 `1` or `true` then
+logging will be turned on by default to stderr about low-level
+details of the HTTP request and responses being sent and received.
+
+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.request("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))
+```
diff --git a/httpx/dispatch/connection.py b/httpx/dispatch/connection.py
index 87c2a6489e..b843c2e53c 100644
--- a/httpx/dispatch/connection.py
+++ b/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})"
diff --git a/httpx/dispatch/connection_pool.py b/httpx/dispatch/connection_pool.py
index eb990a9618..3699209197 100644
--- a/httpx/dispatch/connection_pool.py
+++ b/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()
diff --git a/httpx/dispatch/http11.py b/httpx/dispatch/http11.py
index a54a8d4d8f..6bb178682c 100644
--- a/httpx/dispatch/http11.py
+++ b/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
 
@@ -73,6 +77,12 @@ async def _send_request(
         """
         Send the request method, URL, and headers to the network.
         """
+        logger.debug(
+            f"send_request 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
@@ -128,6 +138,12 @@ async def _receive_response(
                 assert isinstance(event, h11.Response)
                 break  # pragma: no cover
         http_version = "HTTP/%s" % event.http_version.decode("latin-1", errors="ignore")
+        logger.debug(
+            f"receive_response "
+            f"status_code={event.status_code} "
+            f"headers={event.headers!r}"
+        )
+
         return http_version, event.status_code, event.headers
 
     async def _receive_response_data(
@@ -150,6 +166,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)})")
+            else:
+                logger.debug(f"receive_event event={event!r}")
+
             if event is h11.NEED_DATA:
                 try:
                     data = await self.stream.read(
@@ -164,6 +186,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
diff --git a/httpx/dispatch/http2.py b/httpx/dispatch/http2.py
index f0ea158836..f1f6aade38 100644
--- a/httpx/dispatch/http2.py
+++ b/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,9 @@ 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 stream_id={stream_id} 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 +106,15 @@ 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)})")
+
             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 +161,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()
diff --git a/httpx/models.py b/httpx/models.py
index 4016f89a9f..c511819cc5 100644
--- a/httpx/models.py
+++ b/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]):
     """
diff --git a/httpx/utils.py b/httpx/utils.py
index 6961326330..39f55d1fa0 100644
--- a/httpx/utils.py
+++ b/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,31 @@ 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 the user wants debug logging on we set it up for them.
+    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)
diff --git a/mkdocs.yml b/mkdocs.yml
index 1d00aecfbb..b62bc50b36 100644
--- a/mkdocs.yml
+++ b/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'
diff --git a/setup.cfg b/setup.cfg
index 3077d46061..c8ed45fa63 100644
--- a/setup.cfg
+++ b/setup.cfg
@@ -11,7 +11,7 @@ combine_as_imports = True
 force_grid_wrap = 0
 include_trailing_comma = True
 known_first_party = httpx
-known_third_party = brotli,certifi,chardet,cryptography,h11,h2,hstspreload,nox,pytest,rfc3986,setuptools,trustme,uvicorn
+known_third_party = brotli,certifi,chardet,cryptography,h11,h2,hstspreload,nox,pytest,rfc3986,setuptools,tests,trustme,uvicorn
 line_length = 88
 multi_line_output = 3
 
diff --git a/tests/dispatch/utils.py b/tests/dispatch/utils.py
index b86552dc6b..2eb735a0ff 100644
--- a/tests/dispatch/utils.py
+++ b/tests/dispatch/utils.py
@@ -4,9 +4,9 @@
 import h2.config
 import h2.connection
 import h2.events
+from tests.concurrency import sleep
 
 from httpx import AsyncioBackend, BaseStream, Request, TimeoutConfig
-from tests.concurrency import sleep
 
 
 class MockHTTP2Backend:


Code review comments:
diff_hunk: @@ -0,0 +1,47 @@
+Environment Variables
+=====================
+
+The HTTPX library can be configured via environment variables.
+Here are 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 `1` or `true` then
+logging will be turned on by default to stderr about low-level
+details of the HTTP request and responses being sent and received.
+
+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.request("GET", "https://google.com")
path: docs/environment_variables.md
text: @user1:
I think we showcase `.get()` in other examples in the docs. Since `.request()` is not the focus here how about using `.get()` here as well for consistency?

```suggestion
client.get("https://google.com")
```

@author:
Good idea, I personally don't use the method helpers so I need to remember to do that in the docs. :)