From: Florimond Manca Date: Wed, 6 Nov 2019 21:56:25 +0000 (+0100) Subject: Add DEBUG logs of HTTP requests (#502) X-Git-Tag: 0.7.7~5 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=08069e9368e1da5088173bde65c083ecbec92b96;p=thirdparty%2Fhttpx.git Add DEBUG logs of HTTP requests (#502) --- diff --git a/docs/environment_variables.md b/docs/environment_variables.md index 74c2243d..15723fb4 100644 --- a/docs/environment_variables.md +++ b/docs/environment_variables.md @@ -16,9 +16,9 @@ and what function they serve: Valid values: `debug`, `trace` (case-insensitive) -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. +If set to `debug`, then HTTP requests will be logged to `stderr`. This is useful for general purpose reporting of network activity. -The `debug` log level is currently ignored, but is planned to issue high-level logs of HTTP requests. +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: @@ -30,23 +30,50 @@ 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 -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) -20:54:17.651 - httpx.dispatch.connection - connected http_version='HTTP/2' -20:54:17.651 - httpx.dispatch.http2 - send_headers stream_id=1 headers=[(b':method', b'GET'), (b':authority', b'www.google.com'), ...] -20:54:17.652 - httpx.dispatch.http2 - end_stream stream_id=1 -20:54:17.681 - httpx.dispatch.http2 - receive_event stream_id=0 event= -20:54:17.681 - httpx.dispatch.http2 - receive_event stream_id=0 event= -20:54:17.682 - httpx.dispatch.http2 - receive_event stream_id=0 event= -20:54:17.739 - httpx.dispatch.http2 - receive_event stream_id=1 event= -20:54:17.741 - httpx.dispatch.http2 - receive_event stream_id=1 event= -20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=1 event= -20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=1 event= -20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=0 event= -20:54:17.743 - httpx.dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443)) +$ 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=TimeoutConfig(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=TimeoutConfig(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` diff --git a/httpx/client.py b/httpx/client.py index 060dad0a..d54d2fd6 100644 --- a/httpx/client.py +++ b/httpx/client.py @@ -49,7 +49,9 @@ from .models import ( ResponseContent, URLTypes, ) -from .utils import ElapsedTimer, get_environment_proxies, get_netrc +from .utils import ElapsedTimer, get_environment_proxies, get_logger, get_netrc + +logger = get_logger(__name__) class BaseClient: @@ -241,6 +243,12 @@ class BaseClient: finally: await response.close() + status = f"{response.status_code} {response.reason_phrase}" + response_line = f"{response.http_version} {status}" + logger.debug( + f'HTTP Request: {request.method} {request.url} "{response_line}"' + ) + return response def wrap( diff --git a/httpx/utils.py b/httpx/utils.py index bf3420ce..6516af6b 100644 --- a/httpx/utils.py +++ b/httpx/utils.py @@ -194,6 +194,7 @@ def get_logger(name: str) -> Logger: 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"): @@ -202,8 +203,8 @@ def get_logger(name: str) -> Logger: handler = logging.StreamHandler(sys.stderr) handler.setFormatter( logging.Formatter( - fmt="%(asctime)s.%(msecs)03d - %(name)s - %(message)s", - datefmt="%H:%M:%S", + fmt="%(levelname)s [%(asctime)s] %(name)s - %(message)s", + datefmt="%Y-%m-%d %H:%M:%S", ) ) logger.addHandler(handler) diff --git a/tests/conftest.py b/tests/conftest.py index c6968894..ef57caef 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -69,6 +69,8 @@ async def app(scope, receive, send): await echo_body(scope, receive, send) elif scope["path"].startswith("/echo_headers"): await echo_headers(scope, receive, send) + elif scope["path"].startswith("/redirect_301"): + await redirect_301(scope, receive, send) else: await hello_world(scope, receive, send) @@ -147,6 +149,17 @@ async def echo_headers(scope, receive, send): await send({"type": "http.response.body", "body": json.dumps(body).encode()}) +async def redirect_301(scope, receive, send): + await send( + { + "type": "http.response.start", + "status": 301, + "headers": [[b"location", b"/"]], + } + ) + await send({"type": "http.response.body"}) + + SERVER_SCOPE = "session" diff --git a/tests/test_utils.py b/tests/test_utils.py index 959fbf8f..1da08fae 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -108,6 +108,7 @@ async def test_logs_debug(server, capsys): 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 assert "httpx.dispatch.connection_pool" not in stderr @@ -118,9 +119,28 @@ async def test_logs_trace(server, capsys): 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 assert "httpx.dispatch.connection_pool" in stderr +@pytest.mark.asyncio +async def test_logs_redirect_chain(server, capsys): + with override_log_level("debug"): + async with httpx.AsyncClient() 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_get_ssl_cert_file(): # Two environments is not set. assert get_ca_bundle_from_env() is None