From f1157dbc4102ac8e227a0a0bb12a877f592eff58 Mon Sep 17 00:00:00 2001 From: Tom Christie Date: Mon, 20 Mar 2023 11:30:11 +0000 Subject: [PATCH] Use standard logging style (#2547) * Use standard logging style * Add docs for logging * Drop out-of-date HTTPX_LOG_LEVEL variable docs --- docs/environment_variables.md | 64 ------------------------ docs/logging.md | 83 +++++++++++++++++++++++++++++++ httpx/_client.py | 15 +++--- httpx/_config.py | 27 +++++----- httpx/_utils.py | 46 ------------------ mkdocs.yml | 1 + tests/test_utils.py | 92 +++++++++++++++++++++-------------- tests/utils.py | 21 -------- 8 files changed, 163 insertions(+), 186 deletions(-) create mode 100644 docs/logging.md delete mode 100644 tests/utils.py diff --git a/docs/environment_variables.md b/docs/environment_variables.md index d9cc89a58f..71329fc16c 100644 --- 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= -TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event= -TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event= -TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event= -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= -TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event= -TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event= -TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event= -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= -TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event= -TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event= -TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event= -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 new file mode 100644 index 0000000000..4a32240ca8 --- /dev/null +++ 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= +DEBUG [2023-03-16 14:36:20] httpcore - connection.start_tls.started ssl_context= server_hostname='www.example.com' timeout=5.0 +DEBUG [2023-03-16 14:36:20] httpcore - connection.start_tls.complete return_value= +DEBUG [2023-03-16 14:36:20] httpcore - http11.send_request_headers.started request= +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= +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= +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= +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. \ No newline at end of file diff --git a/httpx/_client.py b/httpx/_client.py index 9a759deaee..003d9633fe 100644 --- 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 index 0187eec47e..f46a5bfe6b 100644 --- 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 index 5e0963fad7..c55d33a6f5 100644 --- 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 index 42e6e95de6..9c8819d75a 100644 --- 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: diff --git a/tests/test_utils.py b/tests/test_utils.py index 3d0007723e..3eaf2451d6 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -1,6 +1,8 @@ +import logging import os import random +import certifi import pytest import httpx @@ -14,7 +16,6 @@ parse_header_links, same_origin, ) -from tests.utils import override_log_level from .common import TESTS_DIR @@ -78,42 +79,59 @@ def test_parse_header_links(value, expected): assert parse_header_links(value) == expected -@pytest.mark.anyio -async def test_logs_debug(server, capsys): - with override_log_level("debug"): - async with httpx.AsyncClient() as client: - response = await client.get(server.url) - assert response.status_code == 200 - stderr = capsys.readouterr().err - assert 'HTTP Request: GET http://127.0.0.1:8000/ "HTTP/1.1 200 OK"' in stderr - - -@pytest.mark.anyio -async def test_logs_trace(server, capsys): - with override_log_level("trace"): - async with httpx.AsyncClient() as client: - response = await client.get(server.url) - assert response.status_code == 200 - stderr = capsys.readouterr().err - assert 'HTTP Request: GET http://127.0.0.1:8000/ "HTTP/1.1 200 OK"' in stderr - - -@pytest.mark.anyio -async def test_logs_redirect_chain(server, capsys): - with override_log_level("debug"): - async with httpx.AsyncClient(follow_redirects=True) as client: - response = await client.get(server.url.copy_with(path="/redirect_301")) - assert response.status_code == 200 - - stderr = capsys.readouterr().err.strip() - redirected_request_line, ok_request_line = stderr.split("\n") - assert redirected_request_line.endswith( - "HTTP Request: GET http://127.0.0.1:8000/redirect_301 " - '"HTTP/1.1 301 Moved Permanently"' - ) - assert ok_request_line.endswith( - 'HTTP Request: GET http://127.0.0.1:8000/ "HTTP/1.1 200 OK"' - ) +def test_logging_request(server, caplog): + caplog.set_level(logging.INFO) + with httpx.Client() as client: + response = client.get(server.url) + assert response.status_code == 200 + + assert caplog.record_tuples == [ + ( + "httpx", + logging.INFO, + 'HTTP Request: GET http://127.0.0.1:8000/ "HTTP/1.1 200 OK"', + ) + ] + + +def test_logging_redirect_chain(server, caplog): + caplog.set_level(logging.INFO) + with httpx.Client(follow_redirects=True) as client: + response = client.get(server.url.copy_with(path="/redirect_301")) + assert response.status_code == 200 + + assert caplog.record_tuples == [ + ( + "httpx", + logging.INFO, + 'HTTP Request: GET http://127.0.0.1:8000/redirect_301 "HTTP/1.1 301 Moved Permanently"', + ), + ( + "httpx", + logging.INFO, + 'HTTP Request: GET http://127.0.0.1:8000/ "HTTP/1.1 200 OK"', + ), + ] + + +def test_logging_ssl(caplog): + caplog.set_level(logging.DEBUG) + with httpx.Client(): + pass + + cafile = certifi.where() + assert caplog.record_tuples == [ + ( + "httpx", + logging.DEBUG, + "load_ssl_context verify=True cert=None trust_env=True http2=False", + ), + ( + "httpx", + logging.DEBUG, + f"load_verify_locations cafile='{cafile}'", + ), + ] def test_get_ssl_cert_file(): diff --git a/tests/utils.py b/tests/utils.py deleted file mode 100644 index 96bd05d621..0000000000 --- a/tests/utils.py +++ /dev/null @@ -1,21 +0,0 @@ -import contextlib -import logging -import os -import typing - -from httpx import _utils - - -@contextlib.contextmanager -def override_log_level(log_level: str) -> typing.Iterator[None]: - os.environ["HTTPX_LOG_LEVEL"] = log_level - - # Force a reload on the logging handlers - _utils._LOGGER_INITIALIZED = False - _utils.get_logger("httpx") - - try: - yield - finally: - # Reset the logger so we don't have verbose output in all unit tests - logging.getLogger("httpx").handlers = []