Use standard logging style (#2547)

* Use standard logging style * Add docs for logging * Drop out-of-date HTTPX_LOG_LEVEL variable docs
encode · Mar 20, 2023 · f1157db · f1157db
1 parent 85c5898
commit f1157db
Show file tree

Hide file tree

Showing 8 changed files with 163 additions and 186 deletions.
diff --git a/docs/environment_variables.md b/docs/environment_variables.md
@@ -8,70 +8,6 @@ Environment variables are used by default. To ignore environment variables, `tru
 
 Here is a list of environment variables that HTTPX recognizes and what function they serve:
 
-## `HTTPX_LOG_LEVEL`
-
-Valid values: `debug`, `trace` (case-insensitive)
-
-If set to `debug`, then HTTP requests will be logged to `stderr`. This is useful for general purpose reporting of network activity.
-
-If set to `trace`, then low-level details about the execution of HTTP requests will be logged to `stderr`, in addition to debug log lines. 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
-
-with httpx.Client() as client:
-    r = client.get("https://google.com")
-```
-
-Debug output:
-
-```console
-$ HTTPX_LOG_LEVEL=debug python test_script.py
-DEBUG [2019-11-06 19:11:24] httpx._client - HTTP Request: GET https://google.com "HTTP/1.1 301 Moved Permanently"
-DEBUG [2019-11-06 19:11:24] httpx._client - HTTP Request: GET https://www.google.com/ "HTTP/1.1 200 OK"
-```
-
-Trace output:
-
-```console
-$ HTTPX_LOG_LEVEL=trace python test_script.py
-TRACE [2019-11-06 19:18:56] httpx._dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='google.com' port=443)
-TRACE [2019-11-06 19:18:56] httpx._dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='google.com' port=443))
-TRACE [2019-11-06 19:18:56] httpx._config - load_ssl_context verify=True cert=None trust_env=True http_versions=HTTPVersionConfig(['HTTP/1.1', 'HTTP/2'])
-TRACE [2019-11-06 19:18:56] httpx._config - load_verify_locations cafile=/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/certifi/cacert.pem
-TRACE [2019-11-06 19:18:56] httpx._dispatch.connection - start_connect host='google.com' port=443 timeout=Timeout(timeout=5.0)
-TRACE [2019-11-06 19:18:56] httpx._dispatch.connection - connected http_version='HTTP/2'
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - send_headers stream_id=1 method='GET' target='/' headers=[(b':method', b'GET'), (b':authority', b'google.com'), (b':scheme', b'https'), (b':path', b'/'), (b'user-agent', b'python-httpx/0.7.6'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate, br'), (b'connection', b'keep-alive')]
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - end_stream stream_id=1
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<RemoteSettingsChanged changed_settings:{ChangedSetting(setting=SettingCodes.MAX_CONCURRENT_STREAMS, original_value=None, new_value=100), ChangedSetting(setting=SettingCodes.INITIAL_WINDOW_SIZE, original_value=65535, new_value=1048576), ChangedSetting(setting=SettingCodes.MAX_HEADER_LIST_SIZE, original_value=None, new_value=16384)}>
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<WindowUpdated stream_id:0, delta:983041>
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<SettingsAcknowledged changed_settings:{}>
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event=<ResponseReceived stream_id:1, headers:[(b':status', b'301'), (b'location', b'https://www.google.com/'), (b'content-type', b'text/html; charset=UTF-8'), (b'date', b'Wed, 06 Nov 2019 18:18:56 GMT'), (b'expires', b'Fri, 06 Dec 2019 18:18:56 GMT'), (b'cache-control', b'public, max-age=2592000'), (b'server', b'gws'), (b'content-length', b'220'), (b'x-xss-protection', b'0'), (b'x-frame-options', b'SAMEORIGIN'), (b'alt-svc', b'quic=":443"; ma=2592000; v="46,43",h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000')]>
-DEBUG [2019-11-06 19:18:56] httpx._client - HTTP Request: GET https://google.com "HTTP/2 301 Moved Permanently"
-TRACE [2019-11-06 19:18:56] httpx._dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='www.google.com' port=443)
-TRACE [2019-11-06 19:18:56] httpx._dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
-TRACE [2019-11-06 19:18:56] httpx._config - load_ssl_context verify=True cert=None trust_env=True http_versions=HTTPVersionConfig(['HTTP/1.1', 'HTTP/2'])
-TRACE [2019-11-06 19:18:56] httpx._config - load_verify_locations cafile=/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/certifi/cacert.pem
-TRACE [2019-11-06 19:18:56] httpx._dispatch.connection - start_connect host='www.google.com' port=443 timeout=Timeout(timeout=5.0)
-TRACE [2019-11-06 19:18:56] httpx._dispatch.connection - connected http_version='HTTP/2'
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - send_headers stream_id=1 method='GET' target='/' headers=[(b':method', b'GET'), (b':authority', b'www.google.com'), (b':scheme', b'https'), (b':path', b'/'), (b'user-agent', b'python-httpx/0.7.6'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate, br'), (b'connection', b'keep-alive')]
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - end_stream stream_id=1
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<RemoteSettingsChanged changed_settings:{ChangedSetting(setting=SettingCodes.MAX_CONCURRENT_STREAMS, original_value=None, new_value=100), ChangedSetting(setting=SettingCodes.INITIAL_WINDOW_SIZE, original_value=65535, new_value=1048576), ChangedSetting(setting=SettingCodes.MAX_HEADER_LIST_SIZE, original_value=None, new_value=16384)}>
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<WindowUpdated stream_id:0, delta:983041>
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<SettingsAcknowledged changed_settings:{}>
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event=<ResponseReceived stream_id:1, headers:[(b':status', b'200'), (b'date', b'Wed, 06 Nov 2019 18:18:56 GMT'), (b'expires', b'-1'), (b'cache-control', b'private, max-age=0'), (b'content-type', b'text/html; charset=ISO-8859-1'), (b'p3p', b'CP="This is not a P3P policy! See g.co/p3phelp for more info."'), (b'content-encoding', b'gzip'), (b'server', b'gws'), (b'content-length', b'5073'), (b'x-xss-protection', b'0'), (b'x-frame-options', b'SAMEORIGIN'), (b'set-cookie', b'1P_JAR=2019-11-06-18; expires=Fri, 06-Dec-2019 18:18:56 GMT; path=/; domain=.google.com; SameSite=none'), (b'set-cookie', b'NID=190=m8G9qLxCz2_4HbZI02ON2HTJF4xTvOhoJiS57Hm-OJrNS2eY20LfXMR_u-mLjujeshW5-BTezI69OGpHksT4ZK2TCDsWeU0DF7AmDTjjXFOdj30eIUTpNq7r9aWRvI8UrqiwlIsLkE8Ee3t5PiIiVdSMUcji7dkavGlMUpkMXU8; expires=Thu, 07-May-2020 18:18:56 GMT; path=/; domain=.google.com; HttpOnly'), (b'alt-svc', b'quic=":443"; ma=2592000; v="46,43",h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000')]>
-DEBUG [2019-11-06 19:18:56] httpx._client - HTTP Request: GET https://www.google.com/ "HTTP/2 200 OK"
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:5186, data:1f8b08000000000002ffc55af97adb4692ff3f4f>
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:221, data:>
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event=<StreamEnded stream_id:1>
-TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<PingReceived ping_data:0000000000000000>
-TRACE [2019-11-06 19:18:56] httpx._dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
-TRACE [2019-11-06 19:18:56] httpx._dispatch.connection - close_connection
-```
-
 ## `SSLKEYLOGFILE`
 
 Valid values: a filename

diff --git a/docs/logging.md b/docs/logging.md
@@ -0,0 +1,83 @@
+# Logging
+
+If you need to inspect the internal behaviour of `httpx`, you can use Python's standard logging to output information about the underlying network behaviour.
+
+For example, the following configuration...
+
+```python
+import logging
+import httpx
+
+logging.basicConfig(
+    format="%(levelname)s [%(asctime)s] %(name)s - %(message)s",
+    datefmt="%Y-%m-%d %H:%M:%S",
+    level=logging.DEBUG
+)
+
+httpx.get("https://www.example.com")
+```
+
+Will send debug level output to the console, or wherever `stdout` is directed too...
+
+```
+DEBUG [2023-03-16 14:36:20] httpx - load_ssl_context verify=True cert=None trust_env=True http2=False
+DEBUG [2023-03-16 14:36:20] httpx - load_verify_locations cafile='/Users/tomchristie/GitHub/encode/httpx/venv/lib/python3.10/site-packages/certifi/cacert.pem'
+DEBUG [2023-03-16 14:36:20] httpcore - connection.connect_tcp.started host='www.example.com' port=443 local_address=None timeout=5.0
+DEBUG [2023-03-16 14:36:20] httpcore - connection.connect_tcp.complete return_value=<httpcore.backends.sync.SyncStream object at 0x1068fd270>
+DEBUG [2023-03-16 14:36:20] httpcore - connection.start_tls.started ssl_context=<ssl.SSLContext object at 0x10689aa40> server_hostname='www.example.com' timeout=5.0
+DEBUG [2023-03-16 14:36:20] httpcore - connection.start_tls.complete return_value=<httpcore.backends.sync.SyncStream object at 0x1068fd240>
+DEBUG [2023-03-16 14:36:20] httpcore - http11.send_request_headers.started request=<Request [b'GET']>
+DEBUG [2023-03-16 14:36:20] httpcore - http11.send_request_headers.complete
+DEBUG [2023-03-16 14:36:20] httpcore - http11.send_request_body.started request=<Request [b'GET']>
+DEBUG [2023-03-16 14:36:20] httpcore - http11.send_request_body.complete
+DEBUG [2023-03-16 14:36:20] httpcore - http11.receive_response_headers.started request=<Request [b'GET']>
+DEBUG [2023-03-16 14:36:21] httpcore - http11.receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Content-Encoding', b'gzip'), (b'Accept-Ranges', b'bytes'), (b'Age', b'507675'), (b'Cache-Control', b'max-age=604800'), (b'Content-Type', b'text/html; charset=UTF-8'), (b'Date', b'Thu, 16 Mar 2023 14:36:21 GMT'), (b'Etag', b'"3147526947+ident"'), (b'Expires', b'Thu, 23 Mar 2023 14:36:21 GMT'), (b'Last-Modified', b'Thu, 17 Oct 2019 07:18:26 GMT'), (b'Server', b'ECS (nyb/1D2E)'), (b'Vary', b'Accept-Encoding'), (b'X-Cache', b'HIT'), (b'Content-Length', b'648')])
+INFO [2023-03-16 14:36:21] httpx - HTTP Request: GET https://www.example.com "HTTP/1.1 200 OK"
+DEBUG [2023-03-16 14:36:21] httpcore - http11.receive_response_body.started request=<Request [b'GET']>
+DEBUG [2023-03-16 14:36:21] httpcore - http11.receive_response_body.complete
+DEBUG [2023-03-16 14:36:21] httpcore - http11.response_closed.started
+DEBUG [2023-03-16 14:36:21] httpcore - http11.response_closed.complete
+DEBUG [2023-03-16 14:36:21] httpcore - connection.close.started
+DEBUG [2023-03-16 14:36:21] httpcore - connection.close.complete
+```
+
+Logging output includes information from both the high-level `httpx` logger, and the network-level `httpcore` logger, which can be configured seperately.
+
+For handling more complex logging configurations you might want to use the dictionary configuration style...
+
+```python
+import logging.config
+import httpx
+
+LOGGING_CONFIG = {
+    "version": 1,
+    "handlers": {
+        "default": {
+            "class": "logging.StreamHandler",
+            "formatter": "http",
+            "stream": "ext://sys.stderr"
+        }
+    },
+    "formatters": {
+        "http": {
+            "format": "%(levelname)s [%(asctime)s] %(name)s - %(message)s",
+            "datefmt": "%Y-%m-%d %H:%M:%S",
+        }
+    },
+    'loggers': {
+        'httpx': {
+            'handlers': ['default'],
+            'level': 'DEBUG',
+        },
+        'httpcore': {
+            'handlers': ['default'],
+            'level': 'DEBUG',
+        },
+    }
+}
+
+logging.config.dictConfig(LOGGING_CONFIG)
+httpx.get('https://www.example.com')
+```
+
+The exact formatting of the debug logging may be subject to change across different versions of `httpx` and `httpcore`. If you need to rely on a particular format it is recommended that you pin installation of these packages to fixed versions.
diff --git a/httpx/_client.py b/httpx/_client.py
@@ -1,5 +1,6 @@
 import datetime
 import enum
+import logging
 import typing
 import warnings
 from contextlib import asynccontextmanager, contextmanager
@@ -50,7 +51,6 @@
     Timer,
     URLPattern,
     get_environment_proxies,
-    get_logger,
     is_https_redirect,
     same_origin,
 )
@@ -84,7 +84,7 @@ class UseClientDefault:
 USE_CLIENT_DEFAULT = UseClientDefault()
 
 
-logger = get_logger(__name__)
+logger = logging.getLogger("httpx")
 
 USER_AGENT = f"python-httpx/{__version__}"
 ACCEPT_ENCODING = ", ".join(
@@ -1010,10 +1010,13 @@ def _send_single_request(self, request: Request) -> Response:
         self.cookies.extract_cookies(response)
         response.default_encoding = self._default_encoding
 
-        status = f"{response.status_code} {response.reason_phrase}"
-        response_line = f"{response.http_version} {status}"
-        logger.debug(
-            'HTTP Request: %s %s "%s"', request.method, request.url, response_line
+        logger.info(
+            'HTTP Request: %s %s "%s %d %s"',
+            request.method,
+            request.url,
+            response.http_version,
+            response.status_code,
+            response.reason_phrase,
         )
 
         return response

diff --git a/httpx/_config.py b/httpx/_config.py
@@ -1,3 +1,4 @@
+import logging
 import os
 import ssl
 import sys
@@ -10,7 +11,7 @@
 from ._models import Headers
 from ._types import CertTypes, HeaderTypes, TimeoutTypes, URLTypes, VerifyTypes
 from ._urls import URL
-from ._utils import get_ca_bundle_from_env, get_logger
+from ._utils import get_ca_bundle_from_env
 
 DEFAULT_CIPHERS = ":".join(
     [
@@ -32,7 +33,7 @@
 )
 
 
-logger = get_logger(__name__)
+logger = logging.getLogger("httpx")
 
 
 class UnsetType:
@@ -75,12 +76,12 @@ def __init__(
         self.ssl_context = self.load_ssl_context()
 
     def load_ssl_context(self) -> ssl.SSLContext:
-        logger.trace(
-            f"load_ssl_context "
-            f"verify={self.verify!r} "
-            f"cert={self.cert!r} "
-            f"trust_env={self.trust_env!r} "
-            f"http2={self.http2!r}"
+        logger.debug(
+            "load_ssl_context verify=%r cert=%r trust_env=%r http2=%r",
+            self.verify,
+            self.cert,
+            self.trust_env,
+            self.http2,
         )
 
         if self.verify:
@@ -141,11 +142,13 @@ def load_ssl_context_verify(self) -> ssl.SSLContext:
             pass
 
         if ca_bundle_path.is_file():
-            logger.trace(f"load_verify_locations cafile={ca_bundle_path!s}")
-            context.load_verify_locations(cafile=str(ca_bundle_path))
+            cafile = str(ca_bundle_path)
+            logger.debug("load_verify_locations cafile=%r", cafile)
+            context.load_verify_locations(cafile=cafile)
         elif ca_bundle_path.is_dir():
-            logger.trace(f"load_verify_locations capath={ca_bundle_path!s}")
-            context.load_verify_locations(capath=str(ca_bundle_path))
+            capath = str(ca_bundle_path)
+            logger.debug("load_verify_locations capath=%r", capath)
+            context.load_verify_locations(capath=capath)
 
         self._load_client_certs(context)
 

diff --git a/httpx/_utils.py b/httpx/_utils.py
@@ -1,10 +1,8 @@
 import codecs
 import email.message
-import logging
 import mimetypes
 import os
 import re
-import sys
 import time
 import typing
 from pathlib import Path
@@ -196,50 +194,6 @@ def obfuscate_sensitive_headers(
         yield k, v
 
 
-_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: no cover
-
-
-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
-        logging.addLevelName(TRACE_LOG_LEVEL, "TRACE")
-
-        log_level = os.environ.get("HTTPX_LOG_LEVEL", "").upper()
-        if log_level in ("DEBUG", "TRACE"):
-            logger = logging.getLogger("httpx")
-            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)
-
-
 def port_or_default(url: "URL") -> typing.Optional[int]:
     if url.port is not None:
         return url.port

diff --git a/mkdocs.yml b/mkdocs.yml
@@ -31,6 +31,7 @@ nav:
     - Guides:
         - Async Support: 'async.md'
         - HTTP/2 Support: 'http2.md'
+        - Logging: 'logging.md'
         - Requests Compatibility: 'compatibility.md'
         - Troubleshooting: 'troubleshooting.md'
     - API Reference: