Review logging.

[tomchristie]

Prompted by #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:

httpx/httpx/_main.py

Line 479 in 83c81aa

extensions={"trace": functools.partial(trace, verbose=verbose)},

Is this a bug or are the docs wrong?

[tomchristie]

Also, it might be neat if this was also exposed in the command line client.

[stale]

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.

[johtso]

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"

[stale]

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.

[tomchristie]

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?

[tomchristie]

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