diff --git a/httpcore/_async/connection.py b/httpcore/_async/connection.py index be6f6900..d448620f 100644 --- a/httpcore/_async/connection.py +++ b/httpcore/_async/connection.py @@ -3,6 +3,7 @@ from .._backends.auto import AsyncLock, AsyncSocketStream, AutoBackend from .._types import URL, Headers, Origin, TimeoutDict +from .._utils import get_logger from .base import ( AsyncByteStream, AsyncHTTPTransport, @@ -12,6 +13,8 @@ from .http2 import AsyncHTTP2Connection from .http11 import AsyncHTTP11Connection +logger = get_logger(__name__) + class AsyncHTTPConnection(AsyncHTTPTransport): def __init__( @@ -56,6 +59,9 @@ async def request( async with self.request_lock: if self.state == ConnectionState.PENDING: if not self.socket: + logger.trace( + "open_socket origin=%r timeout=%r", self.origin, timeout + ) self.socket = await self._open_socket(timeout) self._create_connection(self.socket) elif self.state in (ConnectionState.READY, ConnectionState.IDLE): @@ -66,6 +72,9 @@ async def request( raise NewConnectionRequired() assert self.connection is not None + logger.trace( + "connection.request method=%r url=%r headers=%r", method, url, headers + ) return await self.connection.request(method, url, headers, stream, timeout) async def _open_socket(self, timeout: TimeoutDict = None) -> AsyncSocketStream: @@ -82,6 +91,9 @@ async def _open_socket(self, timeout: TimeoutDict = None) -> AsyncSocketStream: def _create_connection(self, socket: AsyncSocketStream) -> None: http_version = socket.get_http_version() + logger.trace( + "create_connection socket=%r http_version=%r", socket, http_version + ) if http_version == "HTTP/2": self.is_http2 = True self.connection = AsyncHTTP2Connection( @@ -110,5 +122,7 @@ def mark_as_ready(self) -> None: async def start_tls(self, hostname: bytes, timeout: TimeoutDict = None) -> None: if self.connection is not None: + logger.trace("start_tls hostname=%r timeout=%r", hostname, timeout) await self.connection.start_tls(hostname, timeout) + logger.trace("start_tls complete hostname=%r timeout=%r", hostname, timeout) self.socket = self.connection.socket diff --git a/httpcore/_async/connection_pool.py b/httpcore/_async/connection_pool.py index 30a72d42..1b9bfffa 100644 --- a/httpcore/_async/connection_pool.py +++ b/httpcore/_async/connection_pool.py @@ -5,6 +5,7 @@ from .._exceptions import PoolTimeout from .._threadlock import ThreadLock from .._types import URL, Headers, Origin, TimeoutDict +from .._utils import get_logger from .base import ( AsyncByteStream, AsyncHTTPTransport, @@ -13,6 +14,8 @@ ) from .connection import AsyncHTTPConnection +logger = get_logger(__name__) + class NullSemaphore(AsyncSemaphore): def __init__(self) -> None: @@ -133,13 +136,17 @@ async def request( # We get-or-create a connection as an atomic operation, to ensure # that HTTP/2 requests issued in close concurrency will end up # on the same connection. + logger.trace("get_connection_from_pool=%r", origin) connection = await self._get_connection_from_pool(origin) if connection is None: connection = AsyncHTTPConnection( origin=origin, http2=self._http2, ssl_context=self._ssl_context, ) + logger.trace("created connection=%r", connection) await self._add_to_pool(connection, timeout=timeout) + else: + logger.trace("reuse connection=%r", connection) try: response = await connection.request( @@ -148,6 +155,7 @@ async def request( except NewConnectionRequired: connection = None except Exception: + logger.trace("remove from pool connection=%r", connection) await self._remove_from_pool(connection) raise diff --git a/httpcore/_async/http11.py b/httpcore/_async/http11.py index 7305bc29..e2d6c984 100644 --- a/httpcore/_async/http11.py +++ b/httpcore/_async/http11.py @@ -6,6 +6,7 @@ from .._backends.auto import AsyncSocketStream from .._exceptions import ProtocolError, map_exceptions from .._types import URL, Headers, TimeoutDict +from .._utils import get_logger from .base import AsyncByteStream, AsyncHTTPTransport, ConnectionState H11Event = Union[ @@ -17,6 +18,8 @@ h11.ConnectionClosed, ] +logger = get_logger(__name__) + class AsyncHTTP11Connection(AsyncHTTPTransport): READ_NUM_BYTES = 4096 @@ -73,6 +76,7 @@ async def _send_request( """ Send the request line and headers. """ + logger.trace("send_request method=%r url=%r headers=%s", method, url, headers) _scheme, _host, _port, target = url event = h11.Request(method=method, target=target, headers=headers) await self._send_event(event, timeout) @@ -85,6 +89,7 @@ async def _send_request_body( """ # Send the request body. async for chunk in stream: + logger.trace("send_data=Data(<%d bytes>)", len(chunk)) event = h11.Data(data=chunk) await self._send_event(event, timeout) @@ -122,8 +127,10 @@ async def _receive_response_data( while True: event = await self._receive_event(timeout) if isinstance(event, h11.Data): + logger.trace("receive_event=Data(<%d bytes>)", len(event.data)) yield bytes(event.data) elif isinstance(event, (h11.EndOfMessage, h11.PAUSED)): + logger.trace("receive_event=%r", event) break async def _receive_event(self, timeout: TimeoutDict) -> H11Event: @@ -132,6 +139,10 @@ async def _receive_event(self, timeout: TimeoutDict) -> H11Event: """ while True: with map_exceptions({h11.RemoteProtocolError: ProtocolError}): + logger.debug( + "h11.RemoteProtocolError exception their_state=%r", + self.h11_state.their_state, + ) event = self.h11_state.next_event() if event is h11.NEED_DATA: @@ -143,6 +154,11 @@ async def _receive_event(self, timeout: TimeoutDict) -> H11Event: return event async def _response_closed(self) -> None: + logger.trace( + "response_closed our_state=%r their_state=%r", + self.h11_state.our_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/httpcore/_async/http2.py b/httpcore/_async/http2.py index 89c80542..9b3ce2d8 100644 --- a/httpcore/_async/http2.py +++ b/httpcore/_async/http2.py @@ -11,6 +11,7 @@ from .._backends.auto import AsyncLock, AsyncSocketStream, AutoBackend from .._exceptions import ProtocolError from .._types import URL, Headers, TimeoutDict +from .._utils import get_logger from .base import ( AsyncByteStream, AsyncHTTPTransport, @@ -18,6 +19,8 @@ NewConnectionRequired, ) +logger = get_logger(__name__) + def get_reason_phrase(status_code: int) -> bytes: try: @@ -128,6 +131,7 @@ async def send_connection_init(self, timeout: TimeoutDict) -> None: h2.settings.SettingCodes.ENABLE_CONNECT_PROTOCOL ] + logger.trace("initiate_connection=%r", self) self.h2_state.initiate_connection() self.h2_state.increment_flow_control_window(2 ** 24) data_to_send = self.h2_state.data_to_send() @@ -141,6 +145,7 @@ def is_connection_dropped(self) -> bool: return self.socket.is_connection_dropped() async def aclose(self) -> None: + logger.trace("close_connection=%r", self) if self.state != ConnectionState.CLOSED: self.state = ConnectionState.CLOSED @@ -184,6 +189,7 @@ async def receive_events(self, timeout: TimeoutDict) -> None: events = self.h2_state.receive_data(data) for event in events: event_stream_id = getattr(event, "stream_id", 0) + logger.trace("receive_event stream_id=%r event=%s", event_stream_id, event) if hasattr(event, "error_code"): raise ProtocolError(event) @@ -197,6 +203,7 @@ async def receive_events(self, timeout: TimeoutDict) -> None: async def send_headers( self, stream_id: int, headers: Headers, end_stream: bool, timeout: TimeoutDict, ) -> None: + logger.trace("send_headers stream_id=%r headers=%r", stream_id, headers) self.h2_state.send_headers(stream_id, headers, end_stream=end_stream) self.h2_state.increment_flow_control_window(2 ** 24, stream_id=stream_id) data_to_send = self.h2_state.data_to_send() @@ -205,11 +212,13 @@ async def send_headers( async def send_data( self, stream_id: int, chunk: bytes, timeout: TimeoutDict ) -> None: + logger.trace("send_data stream_id=%r chunk=%r", stream_id, chunk) self.h2_state.send_data(stream_id, chunk) data_to_send = self.h2_state.data_to_send() await self.socket.write(data_to_send, timeout) async def end_stream(self, stream_id: int, timeout: TimeoutDict) -> None: + logger.trace("end_stream stream_id=%r", stream_id) self.h2_state.end_stream(stream_id) data_to_send = self.h2_state.data_to_send() await self.socket.write(data_to_send, timeout) @@ -222,6 +231,7 @@ async def acknowledge_received_data( await self.socket.write(data_to_send, timeout) async def close_stream(self, stream_id: int) -> None: + logger.trace("close_stream stream_id=%r", stream_id) del self.streams[stream_id] del self.events[stream_id] diff --git a/httpcore/_async/http_proxy.py b/httpcore/_async/http_proxy.py index dbf61630..898681b2 100644 --- a/httpcore/_async/http_proxy.py +++ b/httpcore/_async/http_proxy.py @@ -3,10 +3,13 @@ from .._exceptions import ProxyError from .._types import URL, Headers, Origin, TimeoutDict +from .._utils import get_logger from .base import AsyncByteStream from .connection import AsyncHTTPConnection from .connection_pool import AsyncConnectionPool, ResponseByteStream +logger = get_logger(__name__) + def merge_headers( default_headers: Headers = None, override_headers: Headers = None @@ -85,11 +88,25 @@ async def request( self.proxy_mode == "DEFAULT" and url[0] == b"http" ) or self.proxy_mode == "FORWARD_ONLY": # By default HTTP requests should be forwarded. + logger.trace( + "forward_request proxy_origin=%r proxy_headers=%r method=%r url=%r", + self.proxy_origin, + self.proxy_headers, + method, + url, + ) return await self._forward_request( method, url, headers=headers, stream=stream, timeout=timeout ) else: # By default HTTPS should be tunnelled. + logger.trace( + "tunnel_request proxy_origin=%r proxy_headers=%r method=%r url=%r", + self.proxy_origin, + self.proxy_headers, + method, + url, + ) return await self._tunnel_request( method, url, headers=headers, stream=stream, timeout=timeout ) @@ -169,7 +186,11 @@ async def _tunnel_request( proxy_status_code = proxy_response[1] proxy_reason_phrase = proxy_response[2] proxy_stream = proxy_response[4] - + logger.trace( + "tunnel_response proxy_status_code=%r proxy_reason=%r ", + proxy_status_code, + proxy_reason_phrase, + ) # Read the response data without closing the socket async for _ in proxy_stream: pass diff --git a/httpcore/_sync/connection.py b/httpcore/_sync/connection.py index 7c26d871..4893d614 100644 --- a/httpcore/_sync/connection.py +++ b/httpcore/_sync/connection.py @@ -3,6 +3,7 @@ from .._backends.auto import SyncLock, SyncSocketStream, SyncBackend from .._types import URL, Headers, Origin, TimeoutDict +from .._utils import get_logger from .base import ( SyncByteStream, SyncHTTPTransport, @@ -12,6 +13,8 @@ from .http2 import SyncHTTP2Connection from .http11 import SyncHTTP11Connection +logger = get_logger(__name__) + class SyncHTTPConnection(SyncHTTPTransport): def __init__( @@ -56,6 +59,9 @@ def request( with self.request_lock: if self.state == ConnectionState.PENDING: if not self.socket: + logger.trace( + "open_socket origin=%r timeout=%r", self.origin, timeout + ) self.socket = self._open_socket(timeout) self._create_connection(self.socket) elif self.state in (ConnectionState.READY, ConnectionState.IDLE): @@ -66,6 +72,9 @@ def request( raise NewConnectionRequired() assert self.connection is not None + logger.trace( + "connection.request method=%r url=%r headers=%r", method, url, headers + ) return self.connection.request(method, url, headers, stream, timeout) def _open_socket(self, timeout: TimeoutDict = None) -> SyncSocketStream: @@ -82,6 +91,9 @@ def _open_socket(self, timeout: TimeoutDict = None) -> SyncSocketStream: def _create_connection(self, socket: SyncSocketStream) -> None: http_version = socket.get_http_version() + logger.trace( + "create_connection socket=%r http_version=%r", socket, http_version + ) if http_version == "HTTP/2": self.is_http2 = True self.connection = SyncHTTP2Connection( @@ -110,5 +122,7 @@ def mark_as_ready(self) -> None: def start_tls(self, hostname: bytes, timeout: TimeoutDict = None) -> None: if self.connection is not None: + logger.trace("start_tls hostname=%r timeout=%r", hostname, timeout) self.connection.start_tls(hostname, timeout) + logger.trace("start_tls complete hostname=%r timeout=%r", hostname, timeout) self.socket = self.connection.socket diff --git a/httpcore/_sync/connection_pool.py b/httpcore/_sync/connection_pool.py index d08da742..46cad6fc 100644 --- a/httpcore/_sync/connection_pool.py +++ b/httpcore/_sync/connection_pool.py @@ -5,6 +5,7 @@ from .._exceptions import PoolTimeout from .._threadlock import ThreadLock from .._types import URL, Headers, Origin, TimeoutDict +from .._utils import get_logger from .base import ( SyncByteStream, SyncHTTPTransport, @@ -13,6 +14,8 @@ ) from .connection import SyncHTTPConnection +logger = get_logger(__name__) + class NullSemaphore(SyncSemaphore): def __init__(self) -> None: @@ -133,13 +136,17 @@ def request( # We get-or-create a connection as an atomic operation, to ensure # that HTTP/2 requests issued in close concurrency will end up # on the same connection. + logger.trace("get_connection_from_pool=%r", origin) connection = self._get_connection_from_pool(origin) if connection is None: connection = SyncHTTPConnection( origin=origin, http2=self._http2, ssl_context=self._ssl_context, ) + logger.trace("created connection=%r", connection) self._add_to_pool(connection, timeout=timeout) + else: + logger.trace("reuse connection=%r", connection) try: response = connection.request( @@ -148,6 +155,7 @@ def request( except NewConnectionRequired: connection = None except Exception: + logger.trace("remove from pool connection=%r", connection) self._remove_from_pool(connection) raise diff --git a/httpcore/_sync/http11.py b/httpcore/_sync/http11.py index a949b056..57bd5276 100644 --- a/httpcore/_sync/http11.py +++ b/httpcore/_sync/http11.py @@ -6,6 +6,7 @@ from .._backends.auto import SyncSocketStream from .._exceptions import ProtocolError, map_exceptions from .._types import URL, Headers, TimeoutDict +from .._utils import get_logger from .base import SyncByteStream, SyncHTTPTransport, ConnectionState H11Event = Union[ @@ -17,6 +18,8 @@ h11.ConnectionClosed, ] +logger = get_logger(__name__) + class SyncHTTP11Connection(SyncHTTPTransport): READ_NUM_BYTES = 4096 @@ -73,6 +76,7 @@ def _send_request( """ Send the request line and headers. """ + logger.trace("send_request method=%r url=%r headers=%s", method, url, headers) _scheme, _host, _port, target = url event = h11.Request(method=method, target=target, headers=headers) self._send_event(event, timeout) @@ -85,6 +89,7 @@ def _send_request_body( """ # Send the request body. for chunk in stream: + logger.trace("send_data=Data(<%d bytes>)", len(chunk)) event = h11.Data(data=chunk) self._send_event(event, timeout) @@ -122,8 +127,10 @@ def _receive_response_data( while True: event = self._receive_event(timeout) if isinstance(event, h11.Data): + logger.trace("receive_event=Data(<%d bytes>)", len(event.data)) yield bytes(event.data) elif isinstance(event, (h11.EndOfMessage, h11.PAUSED)): + logger.trace("receive_event=%r", event) break def _receive_event(self, timeout: TimeoutDict) -> H11Event: @@ -132,6 +139,10 @@ def _receive_event(self, timeout: TimeoutDict) -> H11Event: """ while True: with map_exceptions({h11.RemoteProtocolError: ProtocolError}): + logger.debug( + "h11.RemoteProtocolError exception their_state=%r", + self.h11_state.their_state, + ) event = self.h11_state.next_event() if event is h11.NEED_DATA: @@ -143,6 +154,11 @@ def _receive_event(self, timeout: TimeoutDict) -> H11Event: return event def _response_closed(self) -> None: + logger.trace( + "response_closed our_state=%r their_state=%r", + self.h11_state.our_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/httpcore/_sync/http2.py b/httpcore/_sync/http2.py index accd3817..47039235 100644 --- a/httpcore/_sync/http2.py +++ b/httpcore/_sync/http2.py @@ -11,6 +11,7 @@ from .._backends.auto import SyncLock, SyncSocketStream, SyncBackend from .._exceptions import ProtocolError from .._types import URL, Headers, TimeoutDict +from .._utils import get_logger from .base import ( SyncByteStream, SyncHTTPTransport, @@ -18,6 +19,8 @@ NewConnectionRequired, ) +logger = get_logger(__name__) + def get_reason_phrase(status_code: int) -> bytes: try: @@ -128,6 +131,7 @@ def send_connection_init(self, timeout: TimeoutDict) -> None: h2.settings.SettingCodes.ENABLE_CONNECT_PROTOCOL ] + logger.trace("initiate_connection=%r", self) self.h2_state.initiate_connection() self.h2_state.increment_flow_control_window(2 ** 24) data_to_send = self.h2_state.data_to_send() @@ -141,6 +145,7 @@ def is_connection_dropped(self) -> bool: return self.socket.is_connection_dropped() def close(self) -> None: + logger.trace("close_connection=%r", self) if self.state != ConnectionState.CLOSED: self.state = ConnectionState.CLOSED @@ -184,6 +189,7 @@ def receive_events(self, timeout: TimeoutDict) -> None: events = self.h2_state.receive_data(data) for event in events: event_stream_id = getattr(event, "stream_id", 0) + logger.trace("receive_event stream_id=%r event=%s", event_stream_id, event) if hasattr(event, "error_code"): raise ProtocolError(event) @@ -197,6 +203,7 @@ def receive_events(self, timeout: TimeoutDict) -> None: def send_headers( self, stream_id: int, headers: Headers, end_stream: bool, timeout: TimeoutDict, ) -> None: + logger.trace("send_headers stream_id=%r headers=%r", stream_id, headers) self.h2_state.send_headers(stream_id, headers, end_stream=end_stream) self.h2_state.increment_flow_control_window(2 ** 24, stream_id=stream_id) data_to_send = self.h2_state.data_to_send() @@ -205,11 +212,13 @@ def send_headers( def send_data( self, stream_id: int, chunk: bytes, timeout: TimeoutDict ) -> None: + logger.trace("send_data stream_id=%r chunk=%r", stream_id, chunk) self.h2_state.send_data(stream_id, chunk) data_to_send = self.h2_state.data_to_send() self.socket.write(data_to_send, timeout) def end_stream(self, stream_id: int, timeout: TimeoutDict) -> None: + logger.trace("end_stream stream_id=%r", stream_id) self.h2_state.end_stream(stream_id) data_to_send = self.h2_state.data_to_send() self.socket.write(data_to_send, timeout) @@ -222,6 +231,7 @@ def acknowledge_received_data( self.socket.write(data_to_send, timeout) def close_stream(self, stream_id: int) -> None: + logger.trace("close_stream stream_id=%r", stream_id) del self.streams[stream_id] del self.events[stream_id] diff --git a/httpcore/_sync/http_proxy.py b/httpcore/_sync/http_proxy.py index 716052ef..ab938397 100644 --- a/httpcore/_sync/http_proxy.py +++ b/httpcore/_sync/http_proxy.py @@ -3,10 +3,13 @@ from .._exceptions import ProxyError from .._types import URL, Headers, Origin, TimeoutDict +from .._utils import get_logger from .base import SyncByteStream from .connection import SyncHTTPConnection from .connection_pool import SyncConnectionPool, ResponseByteStream +logger = get_logger(__name__) + def merge_headers( default_headers: Headers = None, override_headers: Headers = None @@ -85,11 +88,25 @@ def request( self.proxy_mode == "DEFAULT" and url[0] == b"http" ) or self.proxy_mode == "FORWARD_ONLY": # By default HTTP requests should be forwarded. + logger.trace( + "forward_request proxy_origin=%r proxy_headers=%r method=%r url=%r", + self.proxy_origin, + self.proxy_headers, + method, + url, + ) return self._forward_request( method, url, headers=headers, stream=stream, timeout=timeout ) else: # By default HTTPS should be tunnelled. + logger.trace( + "tunnel_request proxy_origin=%r proxy_headers=%r method=%r url=%r", + self.proxy_origin, + self.proxy_headers, + method, + url, + ) return self._tunnel_request( method, url, headers=headers, stream=stream, timeout=timeout ) @@ -169,7 +186,11 @@ def _tunnel_request( proxy_status_code = proxy_response[1] proxy_reason_phrase = proxy_response[2] proxy_stream = proxy_response[4] - + logger.trace( + "tunnel_response proxy_status_code=%r proxy_reason=%r ", + proxy_status_code, + proxy_reason_phrase, + ) # Read the response data without closing the socket for _ in proxy_stream: pass diff --git a/httpcore/_utils.py b/httpcore/_utils.py new file mode 100644 index 00000000..fe54042c --- /dev/null +++ b/httpcore/_utils.py @@ -0,0 +1,49 @@ +import logging +import os +import sys +import typing + +_LOGGER_INITIALIZED = False +TRACE_LOG_LEVEL = 5 + + +class Logger(logging.Logger): + # Stub for type checkers. + def trace(self, message: str, *args: typing.Any, **kwargs: typing.Any) -> None: + ... # pragma: nocover + + +def get_logger(name: str) -> Logger: + """ + Get a `logging.Logger` instance, and optionally + set up debug logging based on the HTTPCORE_LOG_LEVEL or HTTPX_LOG_LEVEL + environment variables. + """ + global _LOGGER_INITIALIZED + if not _LOGGER_INITIALIZED: + _LOGGER_INITIALIZED = True + logging.addLevelName(TRACE_LOG_LEVEL, "TRACE") + + log_level = os.environ.get( + "HTTPCORE_LOG_LEVEL", os.environ.get("HTTPX_LOG_LEVEL", "") + ).upper() + if log_level in ("DEBUG", "TRACE"): + logger = logging.getLogger("httpcore") + logger.setLevel(logging.DEBUG if log_level == "DEBUG" else TRACE_LOG_LEVEL) + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter( + logging.Formatter( + fmt="%(levelname)s [%(asctime)s] %(name)s - %(message)s", + datefmt="%Y-%m-%d %H:%M:%S", + ) + ) + logger.addHandler(handler) + + logger = logging.getLogger(name) + + def trace(message: str, *args: typing.Any, **kwargs: typing.Any) -> None: + logger.log(TRACE_LOG_LEVEL, message, *args, **kwargs) + + logger.trace = trace # type: ignore + + return typing.cast(Logger, logger)