Convert debug logs to trace logs (#500)

* Convert debug logs to trace logs

* Update environment variables docs

* Update logging test

docs/environment_variables.md

@@ -11,16 +11,14 @@ There are two ways to set `trust_env` to disable environment variables:
 Here is a list of environment variables that HTTPX recognizes
 and what function they serve:
 
-`HTTPX_DEBUG`
------------
+`HTTPX_LOG_LEVEL`
+-----------------
 
-Valid values: `1`, `true`
+Valid values: `debug`, `trace` (case-insensitive)
 
-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`.
+If set to `trace`, 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.
 
-This can help you debug issues and see what's exactly being sent
-over the wire and to which location.
+The `debug` log level is currently ignored, but is planned to issue high-level logs of HTTP requests.
 
 Example:
 
@@ -33,7 +31,7 @@ with httpx.Client() as client:
 ```
 
 ```console
-user@host:~$ HTTPX_DEBUG=1 python test_script.py
+user@host:~$ HTTPX_LOG_LEVEL=trace 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)

httpx/config.py

@@ -94,7 +94,7 @@ def load_ssl_context(
     ) -> ssl.SSLContext:
         http_versions = HTTPVersionConfig() if http_versions is None else http_versions
 
-        logger.debug(
+        logger.trace(
             f"load_ssl_context "
             f"verify={self.verify!r} "
             f"cert={self.cert!r} "
@@ -163,10 +163,10 @@ def load_ssl_context_verify(
             pass
 
         if ca_bundle_path.is_file():
-            logger.debug(f"load_verify_locations cafile={ca_bundle_path!s}")
+            logger.trace(f"load_verify_locations cafile={ca_bundle_path!s}")
             context.load_verify_locations(cafile=str(ca_bundle_path))
         elif ca_bundle_path.is_dir():
-            logger.debug(f"load_verify_locations capath={ca_bundle_path!s}")
+            logger.trace(f"load_verify_locations capath={ca_bundle_path!s}")
             context.load_verify_locations(capath=str(ca_bundle_path))
 
         self._load_client_certs(context)

httpx/dispatch/connection.py

@@ -84,10 +84,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}")
+        logger.trace(f"start_connect host={host!r} port={port!r} timeout={timeout!r}")
         stream = await self.backend.open_tcp_stream(host, port, ssl_context, timeout)
         http_version = stream.get_http_version()
-        logger.debug(f"connected http_version={http_version!r}")
+        logger.trace(f"connected http_version={http_version!r}")
 
         if http_version == "HTTP/2":
             self.h2_connection = HTTP2Connection(
@@ -109,7 +109,7 @@ async def get_ssl_context(self, ssl: SSLConfig) -> typing.Optional[ssl.SSLContex
         )
 
     async def close(self) -> None:
-        logger.debug("close_connection")
+        logger.trace("close_connection")
         if self.h2_connection is not None:
             await self.h2_connection.close()
         elif self.h11_connection is not None:

httpx/dispatch/connection_pool.py

@@ -128,7 +128,7 @@ async def send(
         return response
 
     async def acquire_connection(self, origin: Origin) -> HTTPConnection:
-        logger.debug(f"acquire_connection origin={origin!r}")
+        logger.trace(f"acquire_connection origin={origin!r}")
         connection = self.pop_connection(origin)
 
         if connection is None:
@@ -143,16 +143,16 @@ async def acquire_connection(self, origin: Origin) -> HTTPConnection:
                 release_func=self.release_connection,
                 trust_env=self.trust_env,
             )
-            logger.debug(f"new_connection connection={connection!r}")
+            logger.trace(f"new_connection connection={connection!r}")
         else:
-            logger.debug(f"reuse_connection connection={connection!r}")
+            logger.trace(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}")
+        logger.trace(f"release_connection connection={connection!r}")
         if connection.is_closed:
             self.active_connections.remove(connection)
             self.max_connections.release()

httpx/dispatch/http11.py

@@ -65,7 +65,7 @@ async def send(
     async def close(self) -> None:
         event = h11.ConnectionClosed()
         try:
-            logger.debug(f"send_event event={event!r}")
+            logger.trace(f"send_event event={event!r}")
             self.h11_state.send(event)
         except h11.LocalProtocolError:  # pragma: no cover
             # Premature client disconnect
@@ -78,7 +78,7 @@ async def _send_request(
         """
         Send the request method, URL, and headers to the network.
         """
-        logger.debug(
+        logger.trace(
             f"send_headers method={request.method!r} "
             f"target={request.url.full_path!r} "
             f"headers={request.headers!r}"
@@ -99,7 +99,7 @@ async def _send_request_data(
         try:
             # Send the request body.
             async for chunk in data:
-                logger.debug(f"send_data data=Data(<{len(chunk)} bytes>)")
+                logger.trace(f"send_data data=Data(<{len(chunk)} bytes>)")
                 event = h11.Data(data=chunk)
                 await self._send_event(event, timeout)
 
@@ -164,9 +164,9 @@ async def _receive_event(self, timeout: TimeoutConfig = None) -> H11Event:
             event = self.h11_state.next_event()
 
             if isinstance(event, h11.Data):
-                logger.debug(f"receive_event event=Data(<{len(event.data)} bytes>)")
+                logger.trace(f"receive_event event=Data(<{len(event.data)} bytes>)")
             else:
-                logger.debug(f"receive_event event={event!r}")
+                logger.trace(f"receive_event event={event!r}")
 
             if event is h11.NEED_DATA:
                 try:
@@ -182,7 +182,7 @@ async def _receive_event(self, timeout: TimeoutConfig = None) -> H11Event:
         return event
 
     async def response_closed(self) -> None:
-        logger.debug(
+        logger.trace(
             f"response_closed "
             f"our_state={self.h11_state.our_state!r} "
             f"their_state={self.h11_state.their_state}"

httpx/dispatch/http2.py

@@ -104,7 +104,7 @@ async def send_headers(
             (b":path", request.url.full_path.encode("ascii")),
         ] + [(k, v) for k, v in request.headers.raw if k != b"host"]
 
-        logger.debug(
+        logger.trace(
             f"send_headers "
             f"stream_id={stream_id} "
             f"method={request.method!r} "
@@ -156,7 +156,7 @@ async def send_data(
                 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}")
+        logger.trace(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)
@@ -207,7 +207,7 @@ async def receive_event(
             events = self.h2_state.receive_data(data)
             for event in events:
                 event_stream_id = getattr(event, "stream_id", 0)
-                logger.debug(
+                logger.trace(
                     f"receive_event stream_id={event_stream_id} event={event!r}"
                 )
 

httpx/dispatch/proxy_http.py

@@ -86,12 +86,12 @@ def __init__(
 
     async def acquire_connection(self, origin: Origin) -> HTTPConnection:
         if self.should_forward_origin(origin):
-            logger.debug(
+            logger.trace(
                 f"forward_connection proxy_url={self.proxy_url!r} origin={origin!r}"
             )
             return await super().acquire_connection(self.proxy_url.origin)
         else:
-            logger.debug(
+            logger.trace(
                 f"tunnel_connection proxy_url={self.proxy_url!r} origin={origin!r}"
             )
             return await self.tunnel_connection(origin)
@@ -143,7 +143,7 @@ async def request_tunnel_proxy_connection(self, origin: Origin) -> HTTPConnectio
 
         # See if our tunnel has been opened successfully
         proxy_response = await connection.send(proxy_request)
-        logger.debug(
+        logger.trace(
             f"tunnel_response "
             f"proxy_url={self.proxy_url!r} "
             f"origin={origin!r} "
@@ -187,7 +187,7 @@ async def tunnel_start_tls(
             ssl_context = await connection.get_ssl_context(ssl_config)
             assert ssl_context is not None
 
-            logger.debug(
+            logger.trace(
                 f"tunnel_start_tls "
                 f"proxy_url={self.proxy_url!r} "
                 f"origin={origin!r}"
@@ -196,7 +196,7 @@ async def tunnel_start_tls(
                 hostname=origin.host, ssl_context=ssl_context, timeout=timeout
             )
             http_version = stream.get_http_version()
-            logger.debug(
+            logger.trace(
                 f"tunnel_tls_complete "
                 f"proxy_url={self.proxy_url!r} "
                 f"origin={origin!r} "

httpx/utils.py

@@ -176,20 +176,29 @@ def obfuscate_sensitive_headers(
 
 
 _LOGGER_INITIALIZED = False
+TRACE_LOG_LEVEL = 5
 
 
-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.
+class Logger(logging.Logger):
+    # Stub for type checkers.
+    def trace(self, message: str, *args: typing.Any, **kwargs: typing.Any) -> None:
+        ...
+
+
+def get_logger(name: str) -> Logger:
+    """
+    Get a `logging.Logger` instance, and optionally
+    set up debug logging based on the HTTPX_LOG_LEVEL environment variable.
     """
     global _LOGGER_INITIALIZED
 
     if not _LOGGER_INITIALIZED:
         _LOGGER_INITIALIZED = True
-        if os.environ.get("HTTPX_DEBUG", "").lower() in ("1", "true"):
+
+        log_level = os.environ.get("HTTPX_LOG_LEVEL", "").upper()
+        if log_level in ("DEBUG", "TRACE"):
             logger = logging.getLogger("httpx")
-            logger.setLevel(logging.DEBUG)
+            logger.setLevel(logging.DEBUG if log_level == "DEBUG" else TRACE_LOG_LEVEL)
             handler = logging.StreamHandler(sys.stderr)
             handler.setFormatter(
                 logging.Formatter(
@@ -199,7 +208,14 @@ def get_logger(name: str) -> logging.Logger:
             )
             logger.addHandler(handler)
 
-    return logging.getLogger(name)
+    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)
 
 
 def kv_format(**kwargs: typing.Any) -> str:
@@ -340,7 +356,7 @@ def asgi_message_with_placeholders(message: dict) -> dict:
 
 
 class MessageLoggerASGIMiddleware:
-    def __init__(self, app: typing.Callable, logger: logging.Logger) -> None:
+    def __init__(self, app: typing.Callable, logger: Logger) -> None:
         self.app = app
         self.logger = logger
 
@@ -350,25 +366,25 @@ async def __call__(
         async def inner_receive() -> dict:
             message = await receive()
             logged_message = asgi_message_with_placeholders(message)
-            self.logger.debug(f"sent {kv_format(**logged_message)}")
+            self.logger.trace(f"sent {kv_format(**logged_message)}")
             return message
 
         async def inner_send(message: dict) -> None:
             logged_message = asgi_message_with_placeholders(message)
-            self.logger.debug(f"received {kv_format(**logged_message)}")
+            self.logger.trace(f"received {kv_format(**logged_message)}")
             await send(message)
 
         logged_scope = dict(scope)
         if "headers" in scope:
             logged_scope["headers"] = list(
                 obfuscate_sensitive_headers(scope["headers"])
             )
-        self.logger.debug(f"started {kv_format(**logged_scope)}")
+        self.logger.trace(f"started {kv_format(**logged_scope)}")
 
         try:
             await self.app(scope, inner_receive, inner_send)
         except BaseException as exc:
-            self.logger.debug("raised_exception")
+            self.logger.trace("raised_exception")
             raise exc from None
         else:
-            self.logger.debug("completed")
+            self.logger.trace("completed")

tests/test_utils.py

@@ -103,9 +103,9 @@ def test_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
+@pytest.mark.parametrize("httpx_log_level", ["trace", "debug"])
+async def test_httpx_log_level_enabled_stderr_logging(server, capsys, httpx_log_level):
+    os.environ["HTTPX_LOG_LEVEL"] = httpx_log_level
 
     # Force a reload on the logging handlers
     utils._LOGGER_INITIALIZED = False
@@ -114,7 +114,7 @@ async def test_httpx_debug_enabled_stderr_logging(server, capsys, httpx_debug):
     async with httpx.AsyncClient() as client:
         await client.get(server.url)
 
-    if httpx_debug in ("1", "True"):
+    if httpx_log_level == "trace":
         assert "httpx.dispatch.connection_pool" in capsys.readouterr().err
     else:
         assert "httpx.dispatch.connection_pool" not in capsys.readouterr().err