Fan out loggers

[tomchristie]

This pull request improves our logging behaviour by fanning out different logger names...

code:

import httpcore
import logging


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


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

console:

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

(output prior to this change)...

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

This allows better control of logging, and also reads more clearly to me.

(parameters passed to the "trace" extension are unaffected by this change.)

TODO

• Implementation
• Update docs
• Include in CHANGELOG

[michaeloliverx]

Anything wrong with logger = logging.getLogger(__name__) at the top of each module that needs a logger?

I find this easier to configure as the name maps to the module import path.

logger = logging.getLogger(__name__) appears in the logging cookbook many times, I don't know if its the "recommended" way but it looks like it.

[adriangb]

That’s definitely the recommended way for applications. For libraries it’s a bit different: you may want your logical model/layout of modules to be different than your physical model/layout. E.g. you probably don’t want logs coming for a private module.

[musale]

LGTM.