httpx
httpx copied to clipboard
Review logging.
Prompted by https://github.com/encode/httpx/discussions/2036
Since the significant httpcore
redesign we've not got our trace logging anymore. I don't think we had a super consistent approach to what did or didn't go in there, so I'd like to review our trace
, debug
, and info
level logging.
Originally posted by jashandeep-sohi January 18, 2022
Per the docs, https://www.python-httpx.org/environment_variables/, I should be able to set set HTTPX_LOG_LEVEL=trace
and it should log detailed information about HTTP requests.
However this does not work (at least for the latest version 0.21.3
). After a little digging, it looks like the only place the trace
extension is actually hooked into is the CLI client: https://github.com/encode/httpx/blob/83c81aa9b8ef0f7825df413a673e6d9300065f3a/httpx/_main.py#L479
Is this a bug or are the docs wrong?
Also, it might be neat if this was also exposed in the command line client.
This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.
I've just bumped into this..
Have been trying to debug a strange issue with a difference in behaviour between httpx 0.20 and 0.21 involving a request hanging indefinitely, but after following the documentation found that I was hardly getting any output in the logs.
httpx 0.20
TRACE [2022-03-17 13:01:20] httpx._config - load_verify_locations cafile=/Users/human/Code/httpx-caching/venv/lib/python3.9/site-packages/certifi/cacert.pem
TRACE [2022-03-17 13:01:20] httpcore._async.connection_pool - get_connection_from_pool=(b'http', b'127.0.0.1', 60321)
TRACE [2022-03-17 13:01:20] httpcore._async.connection_pool - created connection=<AsyncHTTPConnection [Connecting]>
TRACE [2022-03-17 13:01:20] httpcore._async.connection_pool - adding connection to pool=<AsyncHTTPConnection [Connecting]>
TRACE [2022-03-17 13:01:20] httpcore._async.connection - open_socket origin=(b'http', b'127.0.0.1', 60321) timeout={}
TRACE [2022-03-17 13:01:20] httpcore._async.connection - create_connection socket=<httpcore._backends.anyio.SocketStream object at 0x1045bd2b0> http_version='HTTP/1.1'
TRACE [2022-03-17 13:01:20] httpcore._async.connection - connection.handle_async_request method=b'GET' url=(b'http', b'127.0.0.1', 60321, b'/conditional_get') headers=[(b'Host', b'127.0.0.1:60321'), (b'Accept', b'*/*'), (b'Accept-Encoding', b'gzip, deflate'), (b'Connection', b'keep-alive'), (b'User-Agent', b'python-httpx/0.20.0')]
TRACE [2022-03-17 13:01:20] httpcore._async.http11 - send_request method=b'GET' url=(b'http', b'127.0.0.1', 60321, b'/conditional_get') headers=[(b'Host', b'127.0.0.1:60321'), (b'Accept', b'*/*'), (b'Accept-Encoding', b'gzip, deflate'), (b'Connection', b'keep-alive'), (b'User-Agent', b'python-httpx/0.20.0')]
TRACE [2022-03-17 13:01:20] httpcore._async.http11 - send_data=Data(<0 bytes>)
TRACE [2022-03-17 13:01:20] httpcore._async.http11 - receive_event=EndOfMessage(headers=<Headers([])>)
TRACE [2022-03-17 13:01:20] httpcore._async.http11 - response_closed our_state=DONE their_state=DONE
DEBUG [2022-03-17 13:01:20] httpx._client - HTTP Request: GET http://127.0.0.1:60321/conditional_get "HTTP/1.1 304 Not Modified"
TRACE [2022-03-17 13:01:20] httpcore._async.http11 - response_closed our_state=IDLE their_state=IDLE
TRACE [2022-03-17 13:01:20] httpcore._async.connection_pool - removing connection from pool=<AsyncHTTPConnection [HTTP/1.1, CLOSED]>
httpx 0.22
TRACE [2022-03-17 12:54:09] httpx._config - load_ssl_context verify=True cert=None trust_env=True http2=False
TRACE [2022-03-17 12:54:09] httpx._config - load_verify_locations cafile=/Users/human/Code/httpx-caching/venv/lib/python3.9/site-packages/certifi/cacert.pem
DEBUG [2022-03-17 12:54:09] httpx._client - HTTP Request: GET http://127.0.0.1:58544/conditional_get "HTTP/1.1 304 Not Modified"
This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.
This seems us really worth putting a bit of time into.
I think this would be a comprehensive logging output for httpx
.
DEBUG: Client opened
DEBUG: Client closed
DEBUG: SSL config <...>
DEBUG: Request started <...>
DEBUG: Sent <...> bytes content
DEBUG: Request complete
DEBUG: Response started <...>
DEBUG: Received <...> bytes content
DEBUG: Response complete
DEBUG: Request error <...>
INFO: GET https://www.example.com "HTTP/1.1 200 OK"
There's all sorts of things we could include at the httpcore
level, but I'd rather we just start by thinking about the httpx
level, and then progress from there.
I don't think we really need a custom TRACE
level here, if we can avoid it that'd probably be better.
Also, why are setting up a custom formatter at the moment? Could we avoid that and just rely on Python's default setup?
Actually, for httpcore
we already know what we'd want to expose.
Everything that the trace
extension shows is useful to us... https://www.encode.io/httpcore/extensions/#trace
We could either expose that using DEBUG
level logging in httpcore
directly, or we could expose it through httpx
, by using the trace
extension, and keeping a custom TRACE
level.
So either this kind of thing...
DEBUG httpx: Request started <...>
DEBUG httpcore: connection.connect_tcp.started {'host': 'www.example.com', 'port': 443, 'local_address': None, 'timeout': None}
DEBUG httpcore: connection.connect_tcp.complete {'return_value': <httpcore.backends.sync.SyncStream object at 0x1093f94d0>}
DEBUG httpcore: connection.start_tls.started {'ssl_context': <ssl.SSLContext object at 0x1093ee750>, 'server_hostname': b'www.example.com', 'timeout': None}
DEBUG httpcore: connection.start_tls.complete {'return_value': <httpcore.backends.sync.SyncStream object at 0x1093f9450>}
DEBUG httpcore: http11.send_request_headers.started {'request': <Request [b'GET']>}
DEBUG httpcore: http11.send_request_headers.complete {'return_value': None}
DEBUG httpcore: http11.send_request_body.started {'request': <Request [b'GET']>}
DEBUG httpcore: http11.send_request_body.complete {'return_value': None}
DEBUG httpx: Sent <...> bytes content
DEBUG httpx: Request complete
Or this...
DEBUG httpx: Request started <...>
TRACE httpx: connection.connect_tcp.started {'host': 'www.example.com', 'port': 443, 'local_address': None, 'timeout': None}
TRACE httpx: connection.connect_tcp.complete {'return_value': <httpcore.backends.sync.SyncStream object at 0x1093f94d0>}
TRACE httpx: connection.start_tls.started {'ssl_context': <ssl.SSLContext object at 0x1093ee750>, 'server_hostname': b'www.example.com', 'timeout': None}
TRACE httpx: connection.start_tls.complete {'return_value': <httpcore.backends.sync.SyncStream object at 0x1093f9450>}
TRACE httpx: http11.send_request_headers.started {'request': <Request [b'GET']>}
TRACE httpx: http11.send_request_headers.complete {'return_value': None}
TRACE httpx: http11.send_request_body.started {'request': <Request [b'GET']>}
TRACE httpx: http11.send_request_body.complete {'return_value': None}
DEBUG httpx: Sent <...> bytes content
DEBUG httpx: Request complete