encode/httpx
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Add DEBUG logs of HTTP requests (#502)

Browse Source
This commit is contained in:
Florimond Manca 2019-11-06 22:56:25 +01:00 committed by GitHub
parent 2fcf23bbfe
commit 08069e9368
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
5 changed files with 90 additions and 21 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

63
docs/environment_variables.md
View File

@ -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
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=<RemoteSettingsChanged changed_settings:{...}>
20:54:17.681 - httpx.dispatch.http2 - receive_event stream_id=0 event=<WindowUpdated stream_id:0, delta:983041>
20:54:17.682 - httpx.dispatch.http2 - receive_event stream_id=0 event=<SettingsAcknowledged changed_settings:{}>
20:54:17.739 - httpx.dispatch.http2 - receive_event stream_id=1 event=<ResponseReceived stream_id:1, headers:[(b':status', b'200'), ...]>
20:54:17.741 - httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:5224 data:>
20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:59, data:>
20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=1 event=<StreamEnded stream_id:1>
20:54:17.742 - httpx.dispatch.http2 - receive_event stream_id=0 event=<PingReceived ping_data:0000000000000000>
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=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=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=<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=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=<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`

10
httpx/client.py
View File

@ -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(

5
httpx/utils.py
View File

@ -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)

13
tests/conftest.py
View File

@ -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"

20
tests/test_utils.py
View File

@ -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