]> git.ipfire.org Git - thirdparty/httpx.git/commitdiff
Add easier debug logging for users (#277)
authorSeth Michael Larson <sethmichaellarson@gmail.com>
Tue, 27 Aug 2019 16:43:13 +0000 (11:43 -0500)
committerGitHub <noreply@github.com>
Tue, 27 Aug 2019 16:43:13 +0000 (11:43 -0500)
Co-Authored-By: Florimond Manca <florimond.manca@gmail.com>
docs/environment_variables.md [new file with mode: 0644]
httpx/dispatch/connection.py
httpx/dispatch/connection_pool.py
httpx/dispatch/http11.py
httpx/dispatch/http2.py
httpx/models.py
httpx/utils.py
mkdocs.yml
tests/test_utils.py

diff --git a/docs/environment_variables.md b/docs/environment_variables.md
new file mode 100644 (file)
index 0000000..be1b581
--- /dev/null
@@ -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))
+```
index 87c2a6489ef0d981822a5cf1357be752d73d84cf..b843c2e53cdd31fbf3af08ed2f7a52851f13b2a1 100644 (file)
@@ -15,6 +15,7 @@ from ..config import (
     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 @@ from .http11 import HTTP11Connection
 ReleaseCallback = typing.Callable[["HTTPConnection"], typing.Awaitable[None]]
 
 
+logger = get_logger(__name__)
+
+
 class HTTPConnection(AsyncDispatcher):
     def __init__(
         self,
@@ -79,8 +83,10 @@ class HTTPConnection(AsyncDispatcher):
         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 @@ class HTTPConnection(AsyncDispatcher):
         )
 
     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 @@ class HTTPConnection(AsyncDispatcher):
         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})"
index eb990a9618ee4c351b1a32c13c2b2d5e1e5ba111..3699209197ae4bd38e80ee13ca28d4c58443c0b0 100644 (file)
@@ -12,12 +12,16 @@ from ..config import (
     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 @@ class ConnectionPool(AsyncDispatcher):
         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 @@ class ConnectionPool(AsyncDispatcher):
                 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()
index a54a8d4d8f6262c8f4324eb8c7502b219cd3a2a0..7452b226bad48a403058b0358d72b19c34289d5c 100644 (file)
@@ -5,6 +5,7 @@ import h11
 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 @@ H11Event = typing.Union[
 OnReleaseCallback = typing.Callable[[], typing.Awaitable[None]]
 
 
+logger = get_logger(__name__)
+
+
 class HTTP11Connection:
     READ_NUM_BYTES = 4096
 
@@ -61,6 +65,7 @@ class HTTP11Connection:
     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 @@ class HTTP11Connection:
         """
         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 @@ class HTTP11Connection:
         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 @@ class HTTP11Connection:
         """
         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 @@ class HTTP11Connection:
         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
index f0ea1588362a77f19446683990208813fd821a2c..bb83d489b65117ef2ebe23cce0fba79a8c143da1 100644 (file)
@@ -7,6 +7,9 @@ import h2.events
 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 @@ class HTTP2Connection:
             (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 @@ class HTTP2Connection:
         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 @@ class HTTP2Connection:
             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()
index 4016f89a9f1c53f9eab8bb96ac011e790c2f87bc..c511819cc5a8ac08081b3e21744164a8f3a3ea48 100644 (file)
@@ -243,6 +243,12 @@ class Origin:
     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]):
     """
index 6961326330a425953e858f8afe192e4aa6843e1a..0357ea2bd23398217f7fdd4e2b21daeb11980606 100644 (file)
@@ -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)
index 1d00aecfbb5fd4bf494502b54edf0123f733cda2..b62bc50b36be4732a67ca178cf3cbe405cb7a02b 100644 (file)
@@ -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'
index 2b2c7ab8298bbb4f203be125963b13e3053e3e4c..bb2abb4e04781d073000eac48b453ab8d87e92e9 100644 (file)
@@ -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 = []