Skip to content

Commit

Permalink
Use standard logging style (#2547)
Browse files Browse the repository at this point in the history
* Use standard logging style

* Add docs for logging

* Drop out-of-date HTTPX_LOG_LEVEL variable docs
  • Loading branch information
tomchristie authored Mar 20, 2023
1 parent 85c5898 commit f1157db
Show file tree
Hide file tree
Showing 8 changed files with 163 additions and 186 deletions.
64 changes: 0 additions & 64 deletions docs/environment_variables.md
Original file line number Diff line number Diff line change
Expand Up @@ -8,70 +8,6 @@ Environment variables are used by default. To ignore environment variables, `tru

Here is a list of environment variables that HTTPX recognizes and what function they serve:

## `HTTPX_LOG_LEVEL`

Valid values: `debug`, `trace` (case-insensitive)

If set to `debug`, then HTTP requests will be logged to `stderr`. This is useful for general purpose reporting of network activity.

If set to `trace`, then low-level details about the execution of HTTP requests will be logged to `stderr`, in addition to debug log lines. This can help you debug issues and see what's exactly being sent over the wire and to which location.

Example:

```python
# test_script.py
import httpx

with httpx.Client() as client:
r = client.get("https://google.com")
```

Debug output:

```console
$ HTTPX_LOG_LEVEL=debug python test_script.py
DEBUG [2019-11-06 19:11:24] httpx._client - HTTP Request: GET https://google.com "HTTP/1.1 301 Moved Permanently"
DEBUG [2019-11-06 19:11:24] httpx._client - HTTP Request: GET https://www.google.com/ "HTTP/1.1 200 OK"
```

Trace output:

```console
$ HTTPX_LOG_LEVEL=trace python test_script.py
TRACE [2019-11-06 19:18:56] httpx._dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='google.com' port=443)
TRACE [2019-11-06 19:18:56] httpx._dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='google.com' port=443))
TRACE [2019-11-06 19:18:56] httpx._config - load_ssl_context verify=True cert=None trust_env=True http_versions=HTTPVersionConfig(['HTTP/1.1', 'HTTP/2'])
TRACE [2019-11-06 19:18:56] httpx._config - load_verify_locations cafile=/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/certifi/cacert.pem
TRACE [2019-11-06 19:18:56] httpx._dispatch.connection - start_connect host='google.com' port=443 timeout=Timeout(timeout=5.0)
TRACE [2019-11-06 19:18:56] httpx._dispatch.connection - connected http_version='HTTP/2'
TRACE [2019-11-06 19:18:56] 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.6'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate, br'), (b'connection', b'keep-alive')]
TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - end_stream stream_id=1
TRACE [2019-11-06 19:18:56] 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)}>
TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<WindowUpdated stream_id:0, delta:983041>
TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<SettingsAcknowledged changed_settings:{}>
TRACE [2019-11-06 19:18:56] 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'Wed, 06 Nov 2019 18:18:56 GMT'), (b'expires', b'Fri, 06 Dec 2019 18:18:56 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",h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000')]>
DEBUG [2019-11-06 19:18:56] httpx._client - HTTP Request: GET https://google.com "HTTP/2 301 Moved Permanently"
TRACE [2019-11-06 19:18:56] httpx._dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='www.google.com' port=443)
TRACE [2019-11-06 19:18:56] httpx._dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
TRACE [2019-11-06 19:18:56] httpx._config - load_ssl_context verify=True cert=None trust_env=True http_versions=HTTPVersionConfig(['HTTP/1.1', 'HTTP/2'])
TRACE [2019-11-06 19:18:56] httpx._config - load_verify_locations cafile=/Users/florimond/Developer/python-projects/httpx/venv/lib/python3.8/site-packages/certifi/cacert.pem
TRACE [2019-11-06 19:18:56] httpx._dispatch.connection - start_connect host='www.google.com' port=443 timeout=Timeout(timeout=5.0)
TRACE [2019-11-06 19:18:56] httpx._dispatch.connection - connected http_version='HTTP/2'
TRACE [2019-11-06 19:18:56] 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.6'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate, br'), (b'connection', b'keep-alive')]
TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - end_stream stream_id=1
TRACE [2019-11-06 19:18:56] 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)}>
TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<WindowUpdated stream_id:0, delta:983041>
TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<SettingsAcknowledged changed_settings:{}>
TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event=<ResponseReceived stream_id:1, headers:[(b':status', b'200'), (b'date', b'Wed, 06 Nov 2019 18:18:56 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'5073'), (b'x-xss-protection', b'0'), (b'x-frame-options', b'SAMEORIGIN'), (b'set-cookie', b'1P_JAR=2019-11-06-18; expires=Fri, 06-Dec-2019 18:18:56 GMT; path=/; domain=.google.com; SameSite=none'), (b'set-cookie', b'NID=190=m8G9qLxCz2_4HbZI02ON2HTJF4xTvOhoJiS57Hm-OJrNS2eY20LfXMR_u-mLjujeshW5-BTezI69OGpHksT4ZK2TCDsWeU0DF7AmDTjjXFOdj30eIUTpNq7r9aWRvI8UrqiwlIsLkE8Ee3t5PiIiVdSMUcji7dkavGlMUpkMXU8; expires=Thu, 07-May-2020 18:18:56 GMT; path=/; domain=.google.com; HttpOnly'), (b'alt-svc', b'quic=":443"; ma=2592000; v="46,43",h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000')]>
DEBUG [2019-11-06 19:18:56] httpx._client - HTTP Request: GET https://www.google.com/ "HTTP/2 200 OK"
TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:5186, data:1f8b08000000000002ffc55af97adb4692ff3f4f>
TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event=<DataReceived stream_id:1, flow_controlled_length:221, data:>
TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=1 event=<StreamEnded stream_id:1>
TRACE [2019-11-06 19:18:56] httpx._dispatch.http2 - receive_event stream_id=0 event=<PingReceived ping_data:0000000000000000>
TRACE [2019-11-06 19:18:56] httpx._dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.google.com' port=443))
TRACE [2019-11-06 19:18:56] httpx._dispatch.connection - close_connection
```

## `SSLKEYLOGFILE`

Valid values: a filename
Expand Down
83 changes: 83 additions & 0 deletions docs/logging.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,83 @@
# Logging

If you need to inspect the internal behaviour of `httpx`, you can use Python's standard logging to output information about the underlying network behaviour.

For example, the following configuration...

```python
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")
```

Will send debug level output to the console, or wherever `stdout` is directed too...

```
DEBUG [2023-03-16 14:36:20] httpx - load_ssl_context verify=True cert=None trust_env=True http2=False
DEBUG [2023-03-16 14:36:20] httpx - load_verify_locations cafile='/Users/tomchristie/GitHub/encode/httpx/venv/lib/python3.10/site-packages/certifi/cacert.pem'
DEBUG [2023-03-16 14:36:20] httpcore - connection.connect_tcp.started host='www.example.com' port=443 local_address=None timeout=5.0
DEBUG [2023-03-16 14:36:20] httpcore - connection.connect_tcp.complete return_value=<httpcore.backends.sync.SyncStream object at 0x1068fd270>
DEBUG [2023-03-16 14:36:20] httpcore - connection.start_tls.started ssl_context=<ssl.SSLContext object at 0x10689aa40> server_hostname='www.example.com' timeout=5.0
DEBUG [2023-03-16 14:36:20] httpcore - connection.start_tls.complete return_value=<httpcore.backends.sync.SyncStream object at 0x1068fd240>
DEBUG [2023-03-16 14:36:20] httpcore - http11.send_request_headers.started request=<Request [b'GET']>
DEBUG [2023-03-16 14:36:20] httpcore - http11.send_request_headers.complete
DEBUG [2023-03-16 14:36:20] httpcore - http11.send_request_body.started request=<Request [b'GET']>
DEBUG [2023-03-16 14:36:20] httpcore - http11.send_request_body.complete
DEBUG [2023-03-16 14:36:20] httpcore - http11.receive_response_headers.started request=<Request [b'GET']>
DEBUG [2023-03-16 14:36:21] 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'507675'), (b'Cache-Control', b'max-age=604800'), (b'Content-Type', b'text/html; charset=UTF-8'), (b'Date', b'Thu, 16 Mar 2023 14:36:21 GMT'), (b'Etag', b'"3147526947+ident"'), (b'Expires', b'Thu, 23 Mar 2023 14:36:21 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-03-16 14:36:21] httpx - HTTP Request: GET https://www.example.com "HTTP/1.1 200 OK"
DEBUG [2023-03-16 14:36:21] httpcore - http11.receive_response_body.started request=<Request [b'GET']>
DEBUG [2023-03-16 14:36:21] httpcore - http11.receive_response_body.complete
DEBUG [2023-03-16 14:36:21] httpcore - http11.response_closed.started
DEBUG [2023-03-16 14:36:21] httpcore - http11.response_closed.complete
DEBUG [2023-03-16 14:36:21] httpcore - connection.close.started
DEBUG [2023-03-16 14:36:21] httpcore - connection.close.complete
```

Logging output includes information from both the high-level `httpx` logger, and the network-level `httpcore` logger, which can be configured seperately.

For handling more complex logging configurations you might want to use the dictionary configuration style...

```python
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')
```

The exact formatting of the debug logging may be subject to change across different versions of `httpx` and `httpcore`. If you need to rely on a particular format it is recommended that you pin installation of these packages to fixed versions.
15 changes: 9 additions & 6 deletions httpx/_client.py
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
import datetime
import enum
import logging
import typing
import warnings
from contextlib import asynccontextmanager, contextmanager
Expand Down Expand Up @@ -50,7 +51,6 @@
Timer,
URLPattern,
get_environment_proxies,
get_logger,
is_https_redirect,
same_origin,
)
Expand Down Expand Up @@ -84,7 +84,7 @@ class UseClientDefault:
USE_CLIENT_DEFAULT = UseClientDefault()


logger = get_logger(__name__)
logger = logging.getLogger("httpx")

USER_AGENT = f"python-httpx/{__version__}"
ACCEPT_ENCODING = ", ".join(
Expand Down Expand Up @@ -1010,10 +1010,13 @@ def _send_single_request(self, request: Request) -> Response:
self.cookies.extract_cookies(response)
response.default_encoding = self._default_encoding

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

return response
Expand Down
27 changes: 15 additions & 12 deletions httpx/_config.py
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
import logging
import os
import ssl
import sys
Expand All @@ -10,7 +11,7 @@
from ._models import Headers
from ._types import CertTypes, HeaderTypes, TimeoutTypes, URLTypes, VerifyTypes
from ._urls import URL
from ._utils import get_ca_bundle_from_env, get_logger
from ._utils import get_ca_bundle_from_env

DEFAULT_CIPHERS = ":".join(
[
Expand All @@ -32,7 +33,7 @@
)


logger = get_logger(__name__)
logger = logging.getLogger("httpx")


class UnsetType:
Expand Down Expand Up @@ -75,12 +76,12 @@ def __init__(
self.ssl_context = self.load_ssl_context()

def load_ssl_context(self) -> ssl.SSLContext:
logger.trace(
f"load_ssl_context "
f"verify={self.verify!r} "
f"cert={self.cert!r} "
f"trust_env={self.trust_env!r} "
f"http2={self.http2!r}"
logger.debug(
"load_ssl_context verify=%r cert=%r trust_env=%r http2=%r",
self.verify,
self.cert,
self.trust_env,
self.http2,
)

if self.verify:
Expand Down Expand Up @@ -141,11 +142,13 @@ def load_ssl_context_verify(self) -> ssl.SSLContext:
pass

if ca_bundle_path.is_file():
logger.trace(f"load_verify_locations cafile={ca_bundle_path!s}")
context.load_verify_locations(cafile=str(ca_bundle_path))
cafile = str(ca_bundle_path)
logger.debug("load_verify_locations cafile=%r", cafile)
context.load_verify_locations(cafile=cafile)
elif ca_bundle_path.is_dir():
logger.trace(f"load_verify_locations capath={ca_bundle_path!s}")
context.load_verify_locations(capath=str(ca_bundle_path))
capath = str(ca_bundle_path)
logger.debug("load_verify_locations capath=%r", capath)
context.load_verify_locations(capath=capath)

self._load_client_certs(context)

Expand Down
46 changes: 0 additions & 46 deletions httpx/_utils.py
Original file line number Diff line number Diff line change
@@ -1,10 +1,8 @@
import codecs
import email.message
import logging
import mimetypes
import os
import re
import sys
import time
import typing
from pathlib import Path
Expand Down Expand Up @@ -196,50 +194,6 @@ def obfuscate_sensitive_headers(
yield k, v


_LOGGER_INITIALIZED = False
TRACE_LOG_LEVEL = 5


class Logger(logging.Logger):
# Stub for type checkers.
def trace(self, message: str, *args: typing.Any, **kwargs: typing.Any) -> None:
... # pragma: no cover


def get_logger(name: str) -> Logger:
"""
Get a `logging.Logger` instance, and optionally
set up debug logging based on the HTTPX_LOG_LEVEL environment variable.
"""
global _LOGGER_INITIALIZED

if not _LOGGER_INITIALIZED:
_LOGGER_INITIALIZED = True
logging.addLevelName(TRACE_LOG_LEVEL, "TRACE")

log_level = os.environ.get("HTTPX_LOG_LEVEL", "").upper()
if log_level in ("DEBUG", "TRACE"):
logger = logging.getLogger("httpx")
logger.setLevel(logging.DEBUG if log_level == "DEBUG" else TRACE_LOG_LEVEL)
handler = logging.StreamHandler(sys.stderr)
handler.setFormatter(
logging.Formatter(
fmt="%(levelname)s [%(asctime)s] %(name)s - %(message)s",
datefmt="%Y-%m-%d %H:%M:%S",
)
)
logger.addHandler(handler)

logger = logging.getLogger(name)

def trace(message: str, *args: typing.Any, **kwargs: typing.Any) -> None:
logger.log(TRACE_LOG_LEVEL, message, *args, **kwargs)

logger.trace = trace # type: ignore

return typing.cast(Logger, logger)


def port_or_default(url: "URL") -> typing.Optional[int]:
if url.port is not None:
return url.port
Expand Down
1 change: 1 addition & 0 deletions mkdocs.yml
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,7 @@ nav:
- Guides:
- Async Support: 'async.md'
- HTTP/2 Support: 'http2.md'
- Logging: 'logging.md'
- Requests Compatibility: 'compatibility.md'
- Troubleshooting: 'troubleshooting.md'
- API Reference:
Expand Down
Loading

0 comments on commit f1157db

Please sign in to comment.