Add `DEBUG` level logging. #648

tomchristie · 2023-01-06T10:56:38Z

Example...

import httpcore
import logging


logging.basicConfig(
    format="%(levelname)s [%(asctime)s] %(name)s - %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
    level=logging.DEBUG
)

httpcore.request('GET', 'https://www.example.com')

Output...

DEBUG [2023-01-06 10:41:02] httpcore - connection.connect_tcp.started host='www.example.com' port=443 local_address=None timeout=None
DEBUG [2023-01-06 10:41:02] httpcore - connection.connect_tcp.complete return_value=<httpcore.backends.sync.SyncStream object at 0x108a11978>
DEBUG [2023-01-06 10:41:02] httpcore - connection.start_tls.started ssl_context=<ssl.SSLContext object at 0x1089ecd68> server_hostname='www.example.com' timeout=None
DEBUG [2023-01-06 10:41:02] httpcore - connection.start_tls.complete return_value=<httpcore.backends.sync.SyncStream object at 0x108a11940>
DEBUG [2023-01-06 10:41:02] httpcore - http11.send_request_headers.started request=<Request [b'GET']>
DEBUG [2023-01-06 10:41:02] httpcore - http11.send_request_headers.complete
DEBUG [2023-01-06 10:41:02] httpcore - http11.send_request_body.started request=<Request [b'GET']>
DEBUG [2023-01-06 10:41:02] httpcore - http11.send_request_body.complete
DEBUG [2023-01-06 10:41:02] httpcore - http11.receive_response_headers.started request=<Request [b'GET']>
DEBUG [2023-01-06 10:41:02] httpcore - http11.receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Age', b'541826'), (b'Cache-Control', b'max-age=604800'), (b'Content-Type', b'text/html; charset=UTF-8'), (b'Date', b'Fri, 06 Jan 2023 10:41:02 GMT'), (b'Etag', b'"3147526947+ident"'), (b'Expires', b'Fri, 13 Jan 2023 10:41:02 GMT'), (b'Last-Modified', b'Thu, 17 Oct 2019 07:18:26 GMT'), (b'Server', b'ECS (nyb/1D1B)'), (b'Vary', b'Accept-Encoding'), (b'X-Cache', b'HIT'), (b'Content-Length', b'1256')])
DEBUG [2023-01-06 10:41:02] httpcore - http11.receive_response_body.started request=<Request [b'GET']>
DEBUG [2023-01-06 10:41:02] httpcore - http11.receive_response_body.complete
DEBUG [2023-01-06 10:41:02] httpcore - http11.response_closed.started
DEBUG [2023-01-06 10:41:02] httpcore - http11.response_closed.complete

There's different design decisions that we could make here about...

The logger name. More granular logger names like httpcore.connection, httpcore.http11, httpcore.http2, would probably be preferable really.
Additional logging points. Connection close, and pool information stand out here.
INFO vs DEBUG. We could have INFO level logs just for the basic call-in/exit points of ConnectionPool.handle_request.
Improving the arguments passed. In plenty of places we're internally just passing request around, which is sufficient, but leads to less clear logging and trace info. As an example send_request_headers could be broken down to method, target, headers, timeout.
Improved __repr__ implementations. For example <httpcore.Request 'GET' 'https://www.example.com'>, or <httpcore.SyncStream [bytes read: 0, bytes written: 0, OPEN]>

But this pull request is a minimal starting point that just hooks into our existing trace without making any further changes.

tomchristie · 2023-01-09T14:44:56Z

Added connection close logging...

import logging
import httpcore

logging.basicConfig(
    format="%(levelname)s [%(asctime)s] %(name)s - %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
    level=logging.DEBUG
)

httpcore.request('GET', 'https://www.example.com')

Output:

DEBUG [2023-01-09 14:44:00] httpcore - connection.connect_tcp.started host='www.example.com' port=443 local_address=None timeout=None
DEBUG [2023-01-09 14:44:00] httpcore - connection.connect_tcp.complete return_value=<httpcore.backends.sync.SyncStream object at 0x109ba6610>
DEBUG [2023-01-09 14:44:00] httpcore - connection.start_tls.started ssl_context=<ssl.SSLContext object at 0x109e427b0> server_hostname='www.example.com' timeout=None
DEBUG [2023-01-09 14:44:00] httpcore - connection.start_tls.complete return_value=<httpcore.backends.sync.SyncStream object at 0x109e8b050>
DEBUG [2023-01-09 14:44:00] httpcore - http11.send_request_headers.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:44:00] httpcore - http11.send_request_headers.complete
DEBUG [2023-01-09 14:44:00] httpcore - http11.send_request_body.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:44:00] httpcore - http11.send_request_body.complete
DEBUG [2023-01-09 14:44:00] httpcore - http11.receive_response_headers.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:44:00] httpcore - http11.receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Age', b'572646'), (b'Cache-Control', b'max-age=604800'), (b'Content-Type', b'text/html; charset=UTF-8'), (b'Date', b'Mon, 09 Jan 2023 14:44:00 GMT'), (b'Etag', b'"3147526947+ident"'), (b'Expires', b'Mon, 16 Jan 2023 14:44:00 GMT'), (b'Last-Modified', b'Thu, 17 Oct 2019 07:18:26 GMT'), (b'Server', b'ECS (nyb/1D18)'), (b'Vary', b'Accept-Encoding'), (b'X-Cache', b'HIT'), (b'Content-Length', b'1256')])
DEBUG [2023-01-09 14:44:00] httpcore - http11.receive_response_body.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:44:00] httpcore - http11.receive_response_body.complete
DEBUG [2023-01-09 14:44:00] httpcore - http11.response_closed.started
DEBUG [2023-01-09 14:44:00] httpcore - http11.response_closed.complete
DEBUG [2023-01-09 14:44:00] httpcore - connection.close.started
DEBUG [2023-01-09 14:44:00] httpcore - connection.close.complete

Also...

import logging
import httpcore

logging.basicConfig(
    format="%(levelname)s [%(asctime)s] %(name)s - %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
    level=logging.DEBUG
)


with httpcore.ConnectionPool() as http:
    http.request('GET', 'https://www.example.com')
    http.request('GET', 'https://www.example.com')

Output:

DEBUG [2023-01-09 14:45:27] httpcore - connection.connect_tcp.started host='www.example.com' port=443 local_address=None timeout=None
DEBUG [2023-01-09 14:45:27] httpcore - connection.connect_tcp.complete return_value=<httpcore.backends.sync.SyncStream object at 0x102e56f90>
DEBUG [2023-01-09 14:45:27] httpcore - connection.start_tls.started ssl_context=<ssl.SSLContext object at 0x1035c67b0> server_hostname='www.example.com' timeout=None
DEBUG [2023-01-09 14:45:28] httpcore - connection.start_tls.complete return_value=<httpcore.backends.sync.SyncStream object at 0x10360efd0>
DEBUG [2023-01-09 14:45:28] httpcore - http11.send_request_headers.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:45:28] httpcore - http11.send_request_headers.complete
DEBUG [2023-01-09 14:45:28] httpcore - http11.send_request_body.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:45:28] httpcore - http11.send_request_body.complete
DEBUG [2023-01-09 14:45:28] httpcore - http11.receive_response_headers.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:45:28] httpcore - http11.receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Age', b'564763'), (b'Cache-Control', b'max-age=604800'), (b'Content-Type', b'text/html; charset=UTF-8'), (b'Date', b'Mon, 09 Jan 2023 14:45:28 GMT'), (b'Etag', b'"3147526947+ident"'), (b'Expires', b'Mon, 16 Jan 2023 14:45:28 GMT'), (b'Last-Modified', b'Thu, 17 Oct 2019 07:18:26 GMT'), (b'Server', b'ECS (nyb/1D2F)'), (b'Vary', b'Accept-Encoding'), (b'X-Cache', b'HIT'), (b'Content-Length', b'1256')])
DEBUG [2023-01-09 14:45:28] httpcore - http11.receive_response_body.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:45:28] httpcore - http11.receive_response_body.complete
DEBUG [2023-01-09 14:45:28] httpcore - http11.response_closed.started
DEBUG [2023-01-09 14:45:28] httpcore - http11.response_closed.complete
DEBUG [2023-01-09 14:45:28] httpcore - http11.send_request_headers.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:45:28] httpcore - http11.send_request_headers.complete
DEBUG [2023-01-09 14:45:28] httpcore - http11.send_request_body.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:45:28] httpcore - http11.send_request_body.complete
DEBUG [2023-01-09 14:45:28] httpcore - http11.receive_response_headers.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:45:28] httpcore - http11.receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Age', b'564763'), (b'Cache-Control', b'max-age=604800'), (b'Content-Type', b'text/html; charset=UTF-8'), (b'Date', b'Mon, 09 Jan 2023 14:45:28 GMT'), (b'Etag', b'"3147526947+ident"'), (b'Expires', b'Mon, 16 Jan 2023 14:45:28 GMT'), (b'Last-Modified', b'Thu, 17 Oct 2019 07:18:26 GMT'), (b'Server', b'ECS (nyb/1D2F)'), (b'Vary', b'Accept-Encoding'), (b'X-Cache', b'HIT'), (b'Content-Length', b'1256')])
DEBUG [2023-01-09 14:45:28] httpcore - http11.receive_response_body.started request=<Request [b'GET']>
DEBUG [2023-01-09 14:45:28] httpcore - http11.receive_response_body.complete
DEBUG [2023-01-09 14:45:28] httpcore - http11.response_closed.started
DEBUG [2023-01-09 14:45:28] httpcore - http11.response_closed.complete
DEBUG [2023-01-09 14:45:28] httpcore - connection.close.started
DEBUG [2023-01-09 14:45:28] httpcore - connection.close.complete

florimondmanca

This along with encode/httpx#2547 is looking wonderful. ✨

…into add-debug-logging

tomchristie · 2023-03-16T10:42:56Z

I think this is ready to go.

https://build.opensuse.org/request/show/1084883 by user dirkmueller + dimstar_suse - update to 0.24.0: * The logging behaviour has been changed to be more in-line with other standard Python logging usages. We no longer have a custom `TRACE` log level, and we no longer use the `HTTPX_LOG_LEVEL` environment variable to auto-configure logging. We now have a significant amount of `DEBUG` logging available at the network level. Full documentation is available at https://www.python-httpx.org/logging/ (#2547, encode/httpcore#648) * The `Response.iter_lines()` method now matches the stdlib behaviour and does not include the newline characters. It also resolves a performance issue. (#2423) * Query parameter encoding switches from using + for spaces and %2F for forward slash, to instead using %20 for spaces and treating forward slas

[![Mend Renovate](https://app.renovatebot.com/images/banner.svg)](https://renovatebot.com) This PR contains the following updates: | Package | Change | Age | Adoption | Passing | Confidence | |---|---|---|---|---|---| | [httpx](https://togithub.com/encode/httpx) ([changelog](https://togithub.com/encode/httpx/blob/master/CHANGELOG.md)) | `^0.23.0` -> `^0.27.0` | [![age](https://developer.mend.io/api/mc/badges/age/pypi/httpx/0.27.0?slim=true)](https://docs.renovatebot.com/merge-confidence/) | [![adoption](https://developer.mend.io/api/mc/badges/adoption/pypi/httpx/0.27.0?slim=true)](https://docs.renovatebot.com/merge-confidence/) | [![passing](https://developer.mend.io/api/mc/badges/compatibility/pypi/httpx/0.23.3/0.27.0?slim=true)](https://docs.renovatebot.com/merge-confidence/) | [![confidence](https://developer.mend.io/api/mc/badges/confidence/pypi/httpx/0.23.3/0.27.0?slim=true)](https://docs.renovatebot.com/merge-confidence/) | --- ### Release Notes <details> <summary>encode/httpx (httpx)</summary> ### [`v0.27.0`](https://togithub.com/encode/httpx/blob/HEAD/CHANGELOG.md#0270-21st-February-2024) [Compare Source](https://togithub.com/encode/httpx/compare/0.26.0...0.27.0) ##### Deprecated - The `app=...` shortcut has been deprecated. Use the explicit style of `transport=httpx.WSGITransport()` or `transport=httpx.ASGITransport()` instead. ##### Fixed - Respect the `http1` argument while configuring proxy transports. ([#3023](https://togithub.com/encode/httpx/issues/3023)) - Fix RFC 2069 mode digest authentication. ([#3045](https://togithub.com/encode/httpx/issues/3045)) ### [`v0.26.0`](https://togithub.com/encode/httpx/blob/HEAD/CHANGELOG.md#0260-20th-December-2023) [Compare Source](https://togithub.com/encode/httpx/compare/0.25.2...0.26.0) ##### Added - The `proxy` argument was added. You should use the `proxy` argument instead of the deprecated `proxies`, or use `mounts=` for more complex configurations. ([#2879](https://togithub.com/encode/httpx/issues/2879)) ##### Deprecated - The `proxies` argument is now deprecated. It will still continue to work, but it will be removed in the future. ([#2879](https://togithub.com/encode/httpx/issues/2879)) ##### Fixed - Fix cases of double escaping of URL path components. Allow / as a safe character in the query portion. ([#2990](https://togithub.com/encode/httpx/issues/2990)) - Handle `NO_PROXY` envvar cases when a fully qualified URL is supplied as the value. ([#2741](https://togithub.com/encode/httpx/issues/2741)) - Allow URLs where username or password contains unescaped '@'. ([#2986](https://togithub.com/encode/httpx/issues/2986)) - Ensure ASGI `raw_path` does not include URL query component. ([#2999](https://togithub.com/encode/httpx/issues/2999)) - Ensure `Response.iter_text()` cannot yield empty strings. ([#2998](https://togithub.com/encode/httpx/issues/2998)) ### [`v0.25.2`](https://togithub.com/encode/httpx/blob/HEAD/CHANGELOG.md#0252-24th-November-2023) [Compare Source](https://togithub.com/encode/httpx/compare/0.25.1...0.25.2) ##### Added - Add missing type hints to few `__init__()` methods. ([#2938](https://togithub.com/encode/httpx/issues/2938)) ### [`v0.25.1`](https://togithub.com/encode/httpx/blob/HEAD/CHANGELOG.md#0251-3rd-November-2023) [Compare Source](https://togithub.com/encode/httpx/compare/0.25.0...0.25.1) ##### Added - Add support for Python 3.12. ([#2854](https://togithub.com/encode/httpx/issues/2854)) - Add support for httpcore 1.0 ([#2885](https://togithub.com/encode/httpx/issues/2885)) ##### Fixed - Raise `ValueError` on `Response.encoding` being set after `Response.text` has been accessed. ([#2852](https://togithub.com/encode/httpx/issues/2852)) ### [`v0.25.0`](https://togithub.com/encode/httpx/blob/HEAD/CHANGELOG.md#0250-11th-Sep-2023) [Compare Source](https://togithub.com/encode/httpx/compare/0.24.1...0.25.0) ##### Removed - Drop support for Python 3.7. ([#2813](https://togithub.com/encode/httpx/issues/2813)) ##### Added - Support HTTPS proxies. ([#2845](https://togithub.com/encode/httpx/issues/2845)) - Change the type of `Extensions` from `Mapping[Str, Any]` to `MutableMapping[Str, Any]`. ([#2803](https://togithub.com/encode/httpx/issues/2803)) - Add `socket_options` argument to `httpx.HTTPTransport` and `httpx.AsyncHTTPTransport` classes. ([#2716](https://togithub.com/encode/httpx/issues/2716)) - The `Response.raise_for_status()` method now returns the response instance. For example: `data = httpx.get('...').raise_for_status().json()`. ([#2776](https://togithub.com/encode/httpx/issues/2776)) ##### Fixed - Return `500` error response instead of exceptions when `raise_app_exceptions=False` is set on `ASGITransport`. ([#2669](https://togithub.com/encode/httpx/issues/2669)) - Ensure all `WSGITransport` environs have a `SERVER_PROTOCOL`. ([#2708](https://togithub.com/encode/httpx/issues/2708)) - Always encode forward slashes as `%2F` in query parameters ([#2723](https://togithub.com/encode/httpx/issues/2723)) - Use Mozilla documentation instead of `httpstatuses.com` for HTTP error reference ([#2768](https://togithub.com/encode/httpx/issues/2768)) ### [`v0.24.1`](https://togithub.com/encode/httpx/blob/HEAD/CHANGELOG.md#0241-17th-May-2023) [Compare Source](https://togithub.com/encode/httpx/compare/0.24.0...0.24.1) ##### Added - Provide additional context in some `InvalidURL` exceptions. ([#2675](https://togithub.com/encode/httpx/issues/2675)) ##### Fixed - Fix optional percent-encoding behaviour. ([#2671](https://togithub.com/encode/httpx/issues/2671)) - More robust checking for opening upload files in binary mode. ([#2630](https://togithub.com/encode/httpx/issues/2630)) - Properly support IP addresses in `NO_PROXY` environment variable. ([#2659](https://togithub.com/encode/httpx/issues/2659)) - Set default file for `NetRCAuth()` to `None` to use the stdlib default. ([#2667](https://togithub.com/encode/httpx/issues/2667)) - Set logging request lines to INFO level for async requests, in line with sync requests. ([#2656](https://togithub.com/encode/httpx/issues/2656)) - Fix which gen-delims need to be escaped for path/query/fragment components in URL. ([#2701](https://togithub.com/encode/httpx/issues/2701)) ### [`v0.24.0`](https://togithub.com/encode/httpx/blob/HEAD/CHANGELOG.md#0240-6th-April-2023) [Compare Source](https://togithub.com/encode/httpx/compare/0.23.3...0.24.0) ##### Changed - The logging behaviour has been changed to be more in-line with other standard Python logging usages. We no longer have a custom `TRACE` log level, and we no longer use the `HTTPX_LOG_LEVEL` environment variable to auto-configure logging. We now have a significant amount of `DEBUG` logging available at the network level. Full documentation is available at https://www.python-httpx.org/logging/ ([#2547](https://togithub.com/encode/httpx/issues/2547), [encode/httpcore#648](https://togithub.com/encode/httpcore/issues/648)) - The `Response.iter_lines()` method now matches the stdlib behaviour and does not include the newline characters. It also resolves a performance issue. ([#2423](https://togithub.com/encode/httpx/issues/2423)) - Query parameter encoding switches from using + for spaces and %2F for forward slash, to instead using %20 for spaces and treating forward slash as a safe, unescaped character. This differs from `requests`, but is in line with browser behavior in Chrome, Safari, and Firefox. Both options are RFC valid. ([#2543](https://togithub.com/encode/httpx/issues/2543)) - NetRC authentication is no longer automatically handled, but is instead supported by an explicit `httpx.NetRCAuth()` authentication class. See the documentation at https://www.python-httpx.org/advanced/#netrc-support ([#2525](https://togithub.com/encode/httpx/issues/2525)) ##### Removed - The `rfc3986` dependancy has been removed. ([#2252](https://togithub.com/encode/httpx/issues/2252)) </details> --- ### Configuration 📅 **Schedule**: Branch creation - At any time (no schedule defined), Automerge - At any time (no schedule defined). 🚦 **Automerge**: Disabled by config. Please merge this manually once you are satisfied. ♻ **Rebasing**: Whenever PR becomes conflicted, or you tick the rebase/retry checkbox. 🔕 **Ignore**: Close this PR and you won't be reminded about this update again. --- - [ ] If you want to rebase/retry this PR, check this box --- This PR has been generated by [Mend Renovate](https://www.mend.io/free-developer-tools/renovate/). View repository job log [here](https://developer.mend.io/github/BSStudio/bss-web-file-api).  Co-authored-by: renovate[bot] <29139614+renovate[bot]@users.noreply.github.com>

Add DEBUG level logging

1c076de

tomchristie added the enhancement New feature or request label Jan 6, 2023

tomchristie mentioned this pull request Jan 9, 2023

Use standard logging style encode/httpx#2547

Merged

3 tasks

Add connection.close logging

afbfa83

Update tests

98cd8f9

tomchristie mentioned this pull request Jan 16, 2023

Client sometimes fails with httpx.LocalProtocolError PrefectHQ/prefect#7442

Closed

4 tasks

florimondmanca reviewed Feb 5, 2023

View reviewed changes

tomchristie added 3 commits March 16, 2023 09:57

Merge branch 'master' into add-debug-logging

f767bf4

Add logging documentation

238f0da

Merge branch 'add-debug-logging' of https://github.com/encode/httpcore …

2069b69

…into add-debug-logging

tomchristie requested review from a team and florimondmanca March 16, 2023 10:42

tomchristie mentioned this pull request Mar 16, 2023

Version 0.17.0 #661

Merged

2 tasks

michaeloliverx approved these changes Mar 16, 2023

View reviewed changes

Merge branch 'master' into add-debug-logging

d748412

tomchristie merged commit 4af5e1c into master Mar 16, 2023

tomchristie deleted the add-debug-logging branch March 16, 2023 12:14

tomchristie mentioned this pull request Apr 6, 2023

Version 0.24.0 encode/httpx#2652

Merged

dalf mentioned this pull request Aug 12, 2023

Bump httpx 0.21.2 from to 0.24.1 searxng/searxng#2644

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add `DEBUG` level logging. #648

Add `DEBUG` level logging. #648

tomchristie commented Jan 6, 2023

tomchristie commented Jan 9, 2023 •

edited

Loading

florimondmanca left a comment

tomchristie commented Mar 16, 2023

Add DEBUG level logging. #648

Add DEBUG level logging. #648

Conversation

tomchristie commented Jan 6, 2023

tomchristie commented Jan 9, 2023 • edited Loading

florimondmanca left a comment

Choose a reason for hiding this comment

tomchristie commented Mar 16, 2023

Add `DEBUG` level logging. #648

Add `DEBUG` level logging. #648

tomchristie commented Jan 9, 2023 •

edited

Loading