Use standard logging style #2547

tomchristie · 2023-01-05T15:56:09Z

Closes #2042

This proposal drops some of our customised logging handling to replace it with a more standard setup.

In particular, we would...

Drop our custom TRACE level logging. Instead use INFO for logging requests, and DEBUG for logging the SSL config.
Drop our custom auto-logging setup, previously enabled via HTTPX_LOG_LEVEL.

This would then give us a more standard setup.

For example, logging at INFO level...

import logging
import httpx

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

httpx.get('https://www.example.com')

Output:

INFO [2023-01-05 15:25:26] httpx - HTTP Request: GET https://www.example.com "HTTP/1.1 200 OK"

Or logging at DEBUG level...

import logging
import httpx

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

httpx.get('https://www.example.com')

Output:

DEBUG [2023-01-05 15:26:12] httpx - load_ssl_context verify=True cert=None trust_env=True http2=False
DEBUG [2023-01-05 15:26:12] httpx - load_verify_locations cafile='/Users/tomchristie/GitHub/encode/httpx/venv/lib/python3.10/site-packages/certifi/cacert.pem'
INFO [2023-01-05 15:26:13] httpx - HTTP Request: GET https://www.example.com "HTTP/1.1 200 OK"

I'd suggest that alongside this we'd also add DEBUG level logging into httpcore, at the points where we currently have trace extension.

Once we've done that you'd be able to have debug logging for both httpcore and httpx...

import logging
import httpx

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

httpx.get('https://www.example.com')

Output:

DEBUG [2023-01-05 15:34:30] httpx - load_ssl_context verify=True cert=None trust_env=True http2=False
DEBUG [2023-01-05 15:34:30] httpx - load_verify_locations cafile='/Users/tomchristie/GitHub/encode/httpx/venv/lib/python3.10/site-packages/certifi/cacert.pem'
DEBUG [2023-01-05 15:34:30] httpcore - connection.connect_tcp.started host='www.example.com' port=443 local_address=None timeout=5.0
DEBUG [2023-01-05 15:34:30] httpcore - connection.connect_tcp.complete return_value=<httpcore.backends.sync.SyncStream object at 0x112074370>
DEBUG [2023-01-05 15:34:30] httpcore - connection.start_tls.started ssl_context=<ssl.SSLContext object at 0x1120489c0> server_hostname='www.example.com' timeout=5.0
DEBUG [2023-01-05 15:34:30] httpcore - connection.start_tls.complete return_value=<httpcore.backends.sync.SyncStream object at 0x1120742e0>
DEBUG [2023-01-05 15:34:30] httpcore - http11.send_request_headers.started request=<Request [b'GET']>
DEBUG [2023-01-05 15:34:30] httpcore - http11.send_request_headers.complete return_value=None
DEBUG [2023-01-05 15:34:30] httpcore - http11.send_request_body.started request=<Request [b'GET']>
DEBUG [2023-01-05 15:34:30] httpcore - http11.send_request_body.complete return_value=None
DEBUG [2023-01-05 15:34:30] httpcore - http11.receive_response_headers.started request=<Request [b'GET']>
DEBUG [2023-01-05 15:34:30] httpcore - http11.receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Content-Encoding', b'gzip'), (b'Accept-Ranges', b'bytes'), (b'Age', b'445646'), (b'Cache-Control', b'max-age=604800'), (b'Content-Type', b'text/html; charset=UTF-8'), (b'Date', b'Thu, 05 Jan 2023 15:34:30 GMT'), (b'Etag', b'"3147526947"'), (b'Expires', b'Thu, 12 Jan 2023 15:34:30 GMT'), (b'Last-Modified', b'Thu, 17 Oct 2019 07:18:26 GMT'), (b'Server', b'ECS (nyb/1D2E)'), (b'Vary', b'Accept-Encoding'), (b'X-Cache', b'HIT'), (b'Content-Length', b'648')])
INFO [2023-01-05 15:34:30] httpx - HTTP Request: GET https://www.example.com "HTTP/1.1 200 OK"
DEBUG [2023-01-05 15:34:30] httpcore - http11.receive_response_body.started request=<Request [b'GET']>
DEBUG [2023-01-05 15:34:30] httpcore - http11.receive_response_body.complete return_value=None
DEBUG [2023-01-05 15:34:30] httpcore - http11.response_closed.started 
DEBUG [2023-01-05 15:34:30] httpcore - http11.response_closed.complete return_value=None

Our documentation would also need updating, and could show users examples with both basicConfig and dictConfig, for example...

import logging.config
import httpx

LOGGING_CONFIG = {
    "version": 1,
    "handlers": {
        "default": {
            "class": "logging.StreamHandler",
            "formatter": "http",
            "stream": "ext://sys.stderr"
        }
    },
    "formatters": {
        "http": {
            "format": "%(levelname)s [%(asctime)s] %(name)s - %(message)s",
            "datefmt": "%Y-%m-%d %H:%M:%S",
        }
    },
    'loggers': {
        'httpx': {
            'handlers': ['default'],
            'level': 'DEBUG',
        },
        'httpcore': {
            'handlers': ['default'],
            'level': 'DEBUG',
        },
    }
}

logging.config.dictConfig(LOGGING_CONFIG)
httpx.get('https://www.example.com')

Input to this proposal is welcome. 🙏🏼

TODO:

Implement for httpx
Update documentation
Add DEBUG level logging to httpcore, at the points where we currently have the trace extension.

See also httpcore issue #648

Kludex · 2023-01-05T16:38:37Z

It feels a bit invasive to use the INFO level for logging requests. Can we use DEBUG for both things?

tomchristie · 2023-01-05T18:02:19Z

That'd be reasonable, yup.

If we did want to keep the request logging at DEBUG level, I'd wonder if we should just drop the TRACE level SSL config logging?

zanieb · 2023-01-05T23:32:15Z

What about using httpx.requests for logging request related information and httpx.ssl for logging SSL related information? Then you'll be able to use INFO / DEBUG level logs according to the importance of the log in that domain and users can control levels at the httpx level or for the domain of interest.

tomchristie · 2023-01-06T11:21:23Z

Okay, I've got a PR up for httpcore now.

Let's see how this looks at the moment...

$ python -m venv venv
$ venv/bin/pip install --upgrade pip
$ venv/bin/pip install https://github.com/encode/httpcore/archive/add-debug-logging.zip
$ venv/bin/pip install https://github.com/encode/httpx/archive/review-logging.zip

Then...

example.py:

import logging
import httpx

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

httpx.get('https://www.example.com')

Output...

$ venv/bin/python example.py
DEBUG [2023-01-06 11:13:37] httpx - load_ssl_context verify=True cert=None trust_env=True http2=False
DEBUG [2023-01-06 11:13:37] httpx - load_verify_locations cafile='/Users/tomchristie/Temp/venv/lib/python3.7/site-packages/certifi/cacert.pem'
DEBUG [2023-01-06 11:13:37] httpcore - connection.connect_tcp.started host='www.example.com' port=443 local_address=None timeout=5.0
DEBUG [2023-01-06 11:13:37] httpcore - connection.connect_tcp.complete return_value=<httpcore.backends.sync.SyncStream object at 0x10e336cc0>
DEBUG [2023-01-06 11:13:37] httpcore - connection.start_tls.started ssl_context=<ssl.SSLContext object at 0x10e300a20> server_hostname='www.example.com' timeout=5.0
DEBUG [2023-01-06 11:13:38] httpcore - connection.start_tls.complete return_value=<httpcore.backends.sync.SyncStream object at 0x10e336c88>
DEBUG [2023-01-06 11:13:38] httpcore - http11.send_request_headers.started request=<Request [b'GET']>
DEBUG [2023-01-06 11:13:38] httpcore - http11.send_request_headers.complete
DEBUG [2023-01-06 11:13:38] httpcore - http11.send_request_body.started request=<Request [b'GET']>
DEBUG [2023-01-06 11:13:38] httpcore - http11.send_request_body.complete
DEBUG [2023-01-06 11:13:38] httpcore - http11.receive_response_headers.started request=<Request [b'GET']>
DEBUG [2023-01-06 11:13:38] httpcore - http11.receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Content-Encoding', b'gzip'), (b'Age', b'155784'), (b'Cache-Control', b'max-age=604800'), (b'Content-Type', b'text/html; charset=UTF-8'), (b'Date', b'Fri, 06 Jan 2023 11:13:38 GMT'), (b'Etag', b'"3147526947+gzip"'), (b'Expires', b'Fri, 13 Jan 2023 11:13:38 GMT'), (b'Last-Modified', b'Thu, 17 Oct 2019 07:18:26 GMT'), (b'Server', b'ECS (nyb/1D04)'), (b'Vary', b'Accept-Encoding'), (b'X-Cache', b'HIT'), (b'Content-Length', b'648')])
INFO [2023-01-06 11:13:38] httpx - HTTP Request: GET https://www.example.com "HTTP/1.1 200 OK"
DEBUG [2023-01-06 11:13:38] httpcore - http11.receive_response_body.started request=<Request [b'GET']>
DEBUG [2023-01-06 11:13:38] httpcore - http11.receive_response_body.complete
DEBUG [2023-01-06 11:13:38] httpcore - http11.response_closed.started
DEBUG [2023-01-06 11:13:38] httpcore - http11.response_closed.complete

florimondmanca · 2023-02-05T13:17:14Z

Logging request lines at the INFO level seems right to me. In comparison, SQLAlchemy logs SQL queries at the INFO level as well. https://docs.sqlalchemy.org/en/20/core/engines.html#configuring-logging

tomchristie · 2023-03-16T15:00:03Z

docs/environment_variables.md

-
-Trace output:
-
-```console


Note that this TRACE documentation was already incorrect at this point since we lost httpcore logging for a while.

tomchristie · 2023-03-16T15:01:57Z

There's more that we could do if we wanted to include extra logging here. Eg. client open/close.
But this at least gets us into using a more standard Python logging setup.
Needs to be called out as a behavioural change in the release notes.

Kludex · 2023-03-20T07:17:57Z

httpx/_client.py

-        response_line = f"{response.http_version} {status}"
-        logger.debug(
-            'HTTP Request: %s %s "%s"', request.method, request.url, response_line
+        logger.info(


Based on the other python packages, I don't recall any other python client having an INFO log message level. 🤔

i.e. can't it be debug as well?

It could yes, though it's less useful to have logging if everything is at the same level.
I like the different "show me nothing", "show me the requests", "show me the debug" lighting levels.

(Similar: gunicorn, uvicorn using INFO for requests, and DEBUG for other stuffs)

tomchristie · 2023-03-20T11:24:04Z

thank you for the reviews folks. 💛

Use standard logging style

a21571d

tomchristie mentioned this pull request Jan 6, 2023

Add DEBUG level logging. encode/httpcore#648

Merged

tomchristie added 2 commits January 10, 2023 13:32

Merge branch 'master' into review-logging

ca1f033

Merge branch 'master' into review-logging

c1a0d44

florimondmanca mentioned this pull request Feb 5, 2023

Drop private logger imports from tests/utils.py #2575

Closed

tomchristie added 4 commits February 10, 2023 13:20

Merge branch 'master' into review-logging

e0f9056

Merge branch 'master' into review-logging

6411bb5

Merge branch 'master' into review-logging

21b47da

Add docs for logging

bda2e05

tomchristie marked this pull request as ready for review March 16, 2023 14:52

Drop out-of-date HTTPX_LOG_LEVEL variable docs

e4db10a

tomchristie commented Mar 16, 2023

View reviewed changes

tomchristie requested review from florimondmanca and a team March 16, 2023 15:02

michaeloliverx approved these changes Mar 16, 2023

View reviewed changes

Kludex approved these changes Mar 20, 2023

View reviewed changes

tomchristie merged commit f1157db into master Mar 20, 2023

tomchristie deleted the review-logging branch March 20, 2023 11:30

tomchristie mentioned this pull request Apr 6, 2023

Version 0.24.0 #2652

Merged

oczkers mentioned this pull request Apr 12, 2023

set logging request lines to INFO level for async method also #2656

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Use standard logging style #2547

Use standard logging style #2547

tomchristie commented Jan 5, 2023 •

edited

Loading

Kludex commented Jan 5, 2023

tomchristie commented Jan 5, 2023

zanieb commented Jan 5, 2023

tomchristie commented Jan 6, 2023 •

edited

Loading

florimondmanca commented Feb 5, 2023

tomchristie Mar 16, 2023

tomchristie commented Mar 16, 2023

Kludex Mar 20, 2023

Kludex Mar 20, 2023

tomchristie Mar 20, 2023

tomchristie commented Mar 20, 2023


		Trace output:

		```console

Use standard logging style #2547

Use standard logging style #2547

Conversation

tomchristie commented Jan 5, 2023 • edited Loading

Kludex commented Jan 5, 2023

tomchristie commented Jan 5, 2023

zanieb commented Jan 5, 2023

tomchristie commented Jan 6, 2023 • edited Loading

florimondmanca commented Feb 5, 2023

tomchristie Mar 16, 2023

Choose a reason for hiding this comment

tomchristie commented Mar 16, 2023

Kludex Mar 20, 2023

Choose a reason for hiding this comment

Kludex Mar 20, 2023

Choose a reason for hiding this comment

tomchristie Mar 20, 2023

Choose a reason for hiding this comment

tomchristie commented Mar 20, 2023

tomchristie commented Jan 5, 2023 •

edited

Loading

tomchristie commented Jan 6, 2023 •

edited

Loading