From: Seth Michael Larson Date: Tue, 27 Aug 2019 16:43:13 +0000 (-0500) Subject: Add easier debug logging for users (#277) X-Git-Tag: 0.7.2~3 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=6f4f18652266a9c138bf31c3dc3638055fc24be7;p=thirdparty%2Fhttpx.git Add easier debug logging for users (#277) Co-Authored-By: Florimond Manca --- diff --git a/docs/environment_variables.md b/docs/environment_variables.md new file mode 100644 index 00000000..be1b5810 --- /dev/null +++ b/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= +20:54:17.681 - httpx.dispatch.http2 - receive_event stream_id=0 event= +20:54:17.682 - httpx.dispatch.http2 - receive_event stream_id=0 event= +20:54:17.739 - httpx.dispatch.http2 - receive_event stream_id=1 event= +20:54:17.741 - httpx.dispatch.http2 - receive_event stream_id=1 event= +20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=1 event= +20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=1 event= +20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=0 event= +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 87c2a648..b843c2e5 100644 --- a/httpx/dispatch/connection.py +++ b/httpx/dispatch/connection.py @@ -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})" diff --git a/httpx/dispatch/connection_pool.py b/httpx/dispatch/connection_pool.py index eb990a96..36992091 100644 --- a/httpx/dispatch/connection_pool.py +++ b/httpx/dispatch/connection_pool.py @@ -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() diff --git a/httpx/dispatch/http11.py b/httpx/dispatch/http11.py index a54a8d4d..7452b226 100644 --- a/httpx/dispatch/http11.py +++ b/httpx/dispatch/http11.py @@ -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 diff --git a/httpx/dispatch/http2.py b/httpx/dispatch/http2.py index f0ea1588..bb83d489 100644 --- a/httpx/dispatch/http2.py +++ b/httpx/dispatch/http2.py @@ -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() diff --git a/httpx/models.py b/httpx/models.py index 4016f89a..c511819c 100644 --- a/httpx/models.py +++ b/httpx/models.py @@ -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]): """ diff --git a/httpx/utils.py b/httpx/utils.py index 69613263..0357ea2b 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,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) diff --git a/mkdocs.yml b/mkdocs.yml index 1d00aecf..b62bc50b 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/tests/test_utils.py b/tests/test_utils.py index 2b2c7ab8..bb2abb4e 100644 --- a/tests/test_utils.py +++ b/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 = []