Add easier debug logging for users #277

sethmlarson · 2019-08-26T11:58:35Z

This builds on #240 and adds it to all request-making dispatchers. It can be added to ASGI and WSGI dispatchers as well but I'm less familiar with what information would be useful for debugging those use-cases.

This also adds a new environment variable HTTPX_DEBUG which can be turned on to automatically display these debug logs.

A new section Environment Variables has been added to the documentation with the intent of future expansion for all environment variables that HTTPX will react to.

Closes #221.

florimondmanca · 2019-08-26T12:10:56Z

This is a great idea. I'll take a closer look later, but do you know about structlog? Your key=value logging style here made me think it could be worth considering it (or another structured logging library). :-)

sethmlarson · 2019-08-26T12:13:04Z

I initially thought to use structlog, mostly didn't want to add a dependency just so we can do debug logging on a client library. Are there other structured logging libraries out there?

florimondmanca · 2019-08-26T12:31:21Z

I don't know of other structured logging libraries. But I think the real question here is, as you said: is adding another dependency for debug logs worth it? I'm not sure it is either. :-)

It's probably possible to build our own formatting helper, starting with something really simple.

There's a structured logging section in the Logging cookbook, which could helper us build a helper to be used like this:

from httpx.logging import structured
logger.debug(structured("log message", key="value"))

The cookbook recipe dumps the output as JSON, but we can take inspiration from structlog's rendering implementation here too to achieve the style you've got here.

florimondmanca · 2019-08-26T12:37:26Z

I think all of this can be figured out later as a refactoring step for this PR, though — just jotting down ideas here, but it's not a blocker at all. :-)

florimondmanca

Really excited about how helpful this will be for debugging requests! I left a couple of comments on details.

docs/environment_variables.md

florimondmanca · 2019-08-26T20:15:16Z

docs/environment_variables.md

+Here are a list of environment variables that HTTPX recognizes
+and what function they serve:
+
+HTTPX_DEBUG


Suggested change

HTTPX_DEBUG

`HTTPX_DEBUG`

Doesn't make any display difference using mkdocs-material (I tried it) but we'll go with it anyways :)

Or really? I looked at the "Developer Interface" page and e.g. Client is rendered in a monospace font. Perhaps it's the use of === / --- instead of # and ## for headers?

I checked, and regardless of the header markup style (which I think we could/should convert to using shebangs since that's what we use everywhere else?) I do get monospace when using code fences:

cc: @tomchristie potential mkdocs-material improvement? :)

docs/environment_variables.md

httpx/utils.py

docs/environment_variables.md

florimondmanca · 2019-08-26T20:56:01Z

Also, will this fix #33?

Co-Authored-By: Florimond Manca <[email protected]>

sethmlarson · 2019-08-26T21:18:07Z

Not quite, that issue is way too broad for its own good. Maybe we should close it and open issues with the specific tasks it requires.

florimondmanca

A couple more polish suggestions!

httpx/utils.py

docs/environment_variables.md

sethmlarson · 2019-08-27T00:57:09Z

@florimondmanca Incorporated your suggestions!

florimondmanca

One last suggestion I didn’t see earlier and we’ll be good to merge 🚀

tests/dispatch/utils.py

httpx/dispatch/http11.py

lovelydinosaur · 2019-08-27T11:16:10Z

httpx/dispatch/http11.py

+            f"send_request method={request.method!r} "
+            f"target={request.url.full_path!r} "
+            f"headers={request.headers!r}"
+        )


We probably also want to log the sending of h11.Data and h11.EndOfMessage events, right?

Yeah I can add that!

lovelydinosaur · 2019-08-27T11:17:48Z

Fantastic, I'm loving this!

Couple of comments worth taking a look at.

lovelydinosaur · 2019-08-27T11:33:02Z

Possible later additions here:

INFO level - log responses in an access log like style - method, URL, status code. We'd probably want to include all redirect requests there too.
WARNING level - Dropped connections, invalid responses, timeouts etc. Basically anything where a request was started but no response was available to log.

INFO httpx.client GET https://example.com/redirect-to-home 304 <Location: https://example.com/>
INFO httpx.client GET https://example.com/ 200
WARN http.client GET https://example.com/ Failed with ReadTimeout(...)

sethmlarson · 2019-08-27T12:10:19Z

With the latest change I tried to normalize the two sets of events being logged for HTTP/1.1 and HTTP/2 so they're similar to look at and debug.

HTTP/1.1

07:02:42.128 - httpx.dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='google.com' port=443)
07:02:42.128 - httpx.dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='google.com' port=443))
07:02:42.133 - httpx.dispatch.connection - start_connect host='google.com' port=443 timeout=TimeoutConfig(timeout=5.0)
07:02:42.195 - httpx.dispatch.connection - connected http_version='HTTP/1.1'
07:02:42.195 - httpx.dispatch.http11 - send_headers method='GET' target='/' headers=Headers({'host': 'google.com', 'user-agent': 'python-httpx/0.7.1', 'accept': '*/*', 'accept-encoding': 'gzip, deflate, br', 'connection': 'keep-alive'})
07:02:42.195 - httpx.dispatch.http11 - receive_event event=NEED_DATA
07:02:42.239 - httpx.dispatch.http11 - receive_event event=Response(status_code=301, headers=[(b'location', b'https://www.google.com/'), (b'content-type', b'text/html; charset=UTF-8'), (b'date', b'Tue, 27 Aug 2019 12:02:42 GMT'), (b'expires', b'Thu, 26 Sep 2019 12:02:42 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,39"')], http_version=b'1.1', reason=b'Moved Permanently')
07:02:42.241 - httpx.dispatch.http11 - response_closed our_state=DONE their_state=SEND_BODY
07:02:42.242 - httpx.dispatch.http11 - send_event event=ConnectionClosed()
07:02:42.242 - httpx.dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='google.com' port=443))
07:02:42.242 - httpx.dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='www.google.com' port=443)
07:02:42.243 - httpx.dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
07:02:42.249 - httpx.dispatch.connection - start_connect host='www.google.com' port=443 timeout=TimeoutConfig(timeout=5.0)
07:02:42.309 - httpx.dispatch.connection - connected http_version='HTTP/1.1'
07:02:42.310 - httpx.dispatch.http11 - send_headers method='GET' target='/' headers=Headers({'host': 'www.google.com', 'user-agent': 'python-httpx/0.7.1', 'accept': '*/*', 'accept-encoding': 'gzip, deflate, br', 'connection': 'keep-alive'})
07:02:42.311 - httpx.dispatch.http11 - receive_event event=NEED_DATA
07:02:42.381 - httpx.dispatch.http11 - receive_event event=Response(status_code=200, headers=[(b'date', b'Tue, 27 Aug 2019 12:02:42 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'x-xss-protection', b'0'), (b'x-frame-options', b'SAMEORIGIN'), (b'set-cookie', b'1P_JAR=2019-08-27-12; expires=Thu, 26-Sep-2019 12:02:42 GMT; path=/; domain=.google.com; SameSite=none'), (b'set-cookie', b'NID=188=Gp8DK6pOzIS9u9wQ_WWtdgqgIYonZLumM5T_UnZ1GrYTwI_c6SJKlX2Ob8RTQMRTUpzinmnoCy5m0kA0gP6ISENfG0LIZ3-ZVBovXWA5kT_R_NubidkP5_haPb-qDGwTG_qrlLBA-kLsIpZNWKpD6t3_E2uOpJFC8jZ2m5I-iJ4; expires=Wed, 26-Feb-2020 12:02:42 GMT; path=/; domain=.google.com; HttpOnly'), (b'alt-svc', b'quic=":443"; ma=2592000; v="46,43,39"'), (b'transfer-encoding', b'chunked')], http_version=b'1.1', reason=b'OK')
07:02:42.383 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.384 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.384 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.385 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.385 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.386 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.387 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.387 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.387 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.388 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.388 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.389 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.389 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.390 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.390 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.391 - httpx.dispatch.http11 - receive_event event=Data(<1 bytes>)
07:02:42.391 - httpx.dispatch.http11 - receive_event event=Data(<2581 bytes>)
07:02:42.392 - httpx.dispatch.http11 - receive_event event=NEED_DATA
07:02:42.392 - httpx.dispatch.http11 - receive_event event=Data(<2439 bytes>)
07:02:42.393 - httpx.dispatch.http11 - receive_event event=EndOfMessage(headers=[])
07:02:42.393 - httpx.dispatch.http11 - response_closed our_state=DONE their_state=DONE
07:02:42.393 - httpx.dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))

HTTP/2

07:04:41.083 - httpx.dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='google.com' port=443)
07:04:41.083 - httpx.dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='google.com' port=443))
07:04:41.088 - httpx.dispatch.connection - start_connect host='google.com' port=443 timeout=TimeoutConfig(timeout=5.0)
07:04:41.166 - httpx.dispatch.connection - connected http_version='HTTP/2'
07:04:41.166 - 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.1'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate, br'), (b'connection', b'keep-alive')]
07:04:41.167 - httpx.dispatch.http2 - end_stream stream_id=1
07:04:41.191 - 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)}>
07:04:41.192 - httpx.dispatch.http2 - receive_event stream_id=0 event=<WindowUpdated stream_id:0, delta:983041>
07:04:41.193 - httpx.dispatch.http2 - receive_event stream_id=0 event=<SettingsAcknowledged changed_settings:{}>
07:04:41.213 - 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'Tue, 27 Aug 2019 12:04:41 GMT'), (b'expires', b'Thu, 26 Sep 2019 12:04:41 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,39"')]>
07:04:41.213 - httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:220, data:3c48544d4c3e3c484541443e3c6d657461206874>
07:04:41.213 - httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:0, data:>
07:04:41.214 - httpx.dispatch.http2 - receive_event stream_id=1 event=<StreamEnded stream_id:1>
07:04:41.214 - httpx.dispatch.http2 - receive_event stream_id=0 event=<PingReceived ping_data:0000000000000000>
07:04:41.217 - httpx.dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='google.com' port=443))
07:04:41.217 - httpx.dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='www.google.com' port=443)
07:04:41.218 - httpx.dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
07:04:41.238 - httpx.dispatch.connection - start_connect host='www.google.com' port=443 timeout=TimeoutConfig(timeout=5.0)
07:04:41.314 - httpx.dispatch.connection - connected http_version='HTTP/2'
07:04:41.315 - 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.1'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate, br'), (b'connection', b'keep-alive')]
07:04:41.317 - httpx.dispatch.http2 - end_stream stream_id=1
07:04:41.338 - 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)}>
07:04:41.339 - httpx.dispatch.http2 - receive_event stream_id=0 event=<WindowUpdated stream_id:0, delta:983041>
07:04:41.339 - httpx.dispatch.http2 - receive_event stream_id=0 event=<SettingsAcknowledged changed_settings:{}>
07:04:41.392 - httpx.dispatch.http2 - receive_event stream_id=1 event=<ResponseReceived stream_id:1, headers:[(b':status', b'200'), (b'date', b'Tue, 27 Aug 2019 12:04:41 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'5048'), (b'x-xss-protection', b'0'), (b'x-frame-options', b'SAMEORIGIN'), (b'set-cookie', b'1P_JAR=2019-08-27-12; expires=Thu, 26-Sep-2019 12:04:41 GMT; path=/; domain=.google.com; SameSite=none'), (b'set-cookie', b'NID=188=prjg5iYy-bcIfsom2sUIFPTHtxxpHicUGQvEJwW2Zs49Sswu69FtIq_A35GRTus9xTLmFUJ66wgENfVEnePNlrx09nadujyCHzyMxS24ucqSkVee6YvAJJHLA6ih-MQMGw-HckU_6hVw4nUOlqIWiN5yqogYs2cG7b96qF4oFTY; expires=Wed, 26-Feb-2020 12:04:41 GMT; path=/; domain=.google.com; HttpOnly'), (b'alt-svc', b'quic=":443"; ma=2592000; v="46,43,39"')]>
07:04:41.395 - httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:5157, data:1f8b08000000000002ffc55ae976dbb6b6fedfa7>
07:04:41.395 - httpx.dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:196, data:>
07:04:41.395 - httpx.dispatch.http2 - receive_event stream_id=1 event=<StreamEnded stream_id:1>
07:04:41.395 - httpx.dispatch.http2 - receive_event stream_id=0 event=<PingReceived ping_data:0000000000000000>
07:04:41.397 - httpx.dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))

httpx/utils.py

florimondmanca

👍👏

sethmlarson · 2019-08-27T16:43:26Z

Thanks for the review @florimondmanca and @tomchristie!

Add easier debug logging for users

7568fcf

florimondmanca self-requested a review August 26, 2019 12:11

florimondmanca suggested changes Aug 26, 2019

View reviewed changes

sethmlarson and others added 3 commits August 26, 2019 16:02

Update docs/environment_variables.md

cdbfe86

Co-Authored-By: Florimond Manca <[email protected]>

Update docs/environment_variables.md

d610c3d

Co-Authored-By: Florimond Manca <[email protected]>

Update docs/environment_variables.md

560e18c

Co-Authored-By: Florimond Manca <[email protected]>

sethmlarson added 2 commits August 26, 2019 16:18

Merge branch 'master' into logging

c518327

Incorperate suggested wording

69650da

florimondmanca mentioned this pull request Aug 26, 2019

Environment support #33

Closed

florimondmanca reviewed Aug 26, 2019

View reviewed changes

httpx/utils.py Outdated Show resolved Hide resolved

docs/environment_variables.md Outdated Show resolved Hide resolved

Suggestions

c083314

florimondmanca suggested changes Aug 27, 2019

View reviewed changes

tests/dispatch/utils.py Show resolved Hide resolved

lovelydinosaur reviewed Aug 27, 2019

View reviewed changes

httpx/dispatch/http11.py Outdated Show resolved Hide resolved

lovelydinosaur reviewed Aug 27, 2019

View reviewed changes

Normalize logging output

3fdb9a8

sethmlarson mentioned this pull request Aug 27, 2019

Add logging to h2 connection #240

Closed

sethmlarson requested review from florimondmanca and lovelydinosaur August 27, 2019 12:47

florimondmanca reviewed Aug 27, 2019

View reviewed changes

httpx/utils.py Outdated Show resolved Hide resolved

Add unit tests for logging

2024938

florimondmanca approved these changes Aug 27, 2019

View reviewed changes

sethmlarson merged commit 6f4f186 into encode:master Aug 27, 2019

sethmlarson deleted the logging branch August 27, 2019 16:43

Uh oh!

Add easier debug logging for users #277

Add easier debug logging for users #277

Uh oh!

Conversation

sethmlarson commented Aug 26, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

florimondmanca commented Aug 26, 2019

Uh oh!

sethmlarson commented Aug 26, 2019

Uh oh!

florimondmanca commented Aug 26, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

florimondmanca commented Aug 26, 2019

Uh oh!

florimondmanca left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

florimondmanca Aug 26, 2019

Choose a reason for hiding this comment

Uh oh!

sethmlarson Aug 26, 2019

Choose a reason for hiding this comment

Uh oh!

florimondmanca Aug 26, 2019

Choose a reason for hiding this comment

Uh oh!

florimondmanca Aug 26, 2019

Choose a reason for hiding this comment

Uh oh!

sethmlarson Aug 27, 2019

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

florimondmanca commented Aug 26, 2019

Uh oh!

sethmlarson commented Aug 26, 2019

Uh oh!

florimondmanca left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

sethmlarson commented Aug 27, 2019

Uh oh!

florimondmanca left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

lovelydinosaur Aug 27, 2019

Choose a reason for hiding this comment

Uh oh!

sethmlarson Aug 27, 2019

Choose a reason for hiding this comment

Uh oh!

lovelydinosaur commented Aug 27, 2019

Uh oh!

lovelydinosaur commented Aug 27, 2019

Uh oh!

sethmlarson commented Aug 27, 2019

Uh oh!

Uh oh!

florimondmanca left a comment

Choose a reason for hiding this comment

Uh oh!

sethmlarson commented Aug 27, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

sethmlarson commented Aug 26, 2019 •

edited

Loading

florimondmanca commented Aug 26, 2019 •

edited

Loading