Add logger trace (#79)

* Add get_logger with trace level support

* Add trace logging calls

* Check HTTPX_LOG_LEVEL as well

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

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
 

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

httpcore/_async/http2.py

@@ -11,13 +11,16 @@
 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,
     ConnectionState,
     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]
 

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

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

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