Fan out loggers

CHANGELOG.md

@@ -6,6 +6,7 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/).
 
 ## development
 
+- Improve logging with per-module logger names. (#690)
 - Resolve race condition during import of `anyio` package. (#692)
 
 ## 0.17.1 (May 17th, 2023)

docs/logging.md

@@ -20,22 +20,22 @@ httpcore.request('GET', 'https://www.example.com')
 Will send debug level output to the console, or wherever `stdout` is directed too...
 
 ```
-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
+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
 ```
 
 The exact formatting of the debug logging may be subject to change across different versions of `httpcore`. If you need to rely on a particular format it is recommended that you pin installation of the package to a fixed version.

httpcore/_async/connection.py

@@ -1,4 +1,5 @@
 import itertools
+import logging
 import ssl
 from types import TracebackType
 from typing import Iterator, Optional, Type
@@ -16,6 +17,9 @@
 RETRIES_BACKOFF_FACTOR = 0.5  # 0s, 0.5s, 1s, 2s, 4s, etc.
 
 
+logger = logging.getLogger("httpcore.connection")
+
+
 def exponential_backoff(factor: float) -> Iterator[float]:
     yield 0
     for n in itertools.count(2):
@@ -105,9 +109,7 @@ async def _connect(self, request: Request) -> AsyncNetworkStream:
                         "local_address": self._local_address,
                         "timeout": timeout,
                     }
-                    async with Trace(
-                        "connection.connect_tcp", request, kwargs
-                    ) as trace:
+                    async with Trace("connect_tcp", logger, request, kwargs) as trace:
                         stream = await self._network_backend.connect_tcp(**kwargs)
                         trace.return_value = stream
                 else:
@@ -116,7 +118,7 @@ async def _connect(self, request: Request) -> AsyncNetworkStream:
                         "timeout": timeout,
                     }
                     async with Trace(
-                        "connection.connect_unix_socket", request, kwargs
+                        "connect_unix_socket", logger, request, kwargs
                     ) as trace:
                         stream = await self._network_backend.connect_unix_socket(
                             **kwargs
@@ -137,7 +139,7 @@ async def _connect(self, request: Request) -> AsyncNetworkStream:
                         "server_hostname": self._origin.host.decode("ascii"),
                         "timeout": timeout,
                     }
-                    async with Trace("connection.start_tls", request, kwargs) as trace:
+                    async with Trace("start_tls", logger, request, kwargs) as trace:
                         stream = await stream.start_tls(**kwargs)
                         trace.return_value = stream
                 return stream
@@ -146,15 +148,15 @@ async def _connect(self, request: Request) -> AsyncNetworkStream:
                     raise
                 retries_left -= 1
                 delay = next(delays)
-                # TRACE 'retry'
-                await self._network_backend.sleep(delay)
+                async with Trace("retry", logger, request, kwargs) as trace:
+                    await self._network_backend.sleep(delay)
 
     def can_handle_request(self, origin: Origin) -> bool:
         return origin == self._origin
 
     async def aclose(self) -> None:
         if self._connection is not None:
-            async with Trace("connection.close", None, {}):
+            async with Trace("close", logger, None, {}):
                 await self._connection.aclose()
 
     def is_available(self) -> bool:

httpcore/_async/http11.py

@@ -1,4 +1,5 @@
 import enum
+import logging
 import time
 from types import TracebackType
 from typing import (
@@ -26,6 +27,9 @@
 from ..backends.base import AsyncNetworkStream
 from .interfaces import AsyncConnectionInterface
 
+logger = logging.getLogger("httpcore.http11")
+
+
 # A subset of `h11.Event` types supported by `_send_event`
 H11SendEvent = Union[
     h11.Request,
@@ -80,12 +84,12 @@ async def handle_async_request(self, request: Request) -> Response:
 
         try:
             kwargs = {"request": request}
-            async with Trace("http11.send_request_headers", request, kwargs) as trace:
+            async with Trace("send_request_headers", logger, request, kwargs) as trace:
                 await self._send_request_headers(**kwargs)
-            async with Trace("http11.send_request_body", request, kwargs) as trace:
+            async with Trace("send_request_body", logger, request, kwargs) as trace:
                 await self._send_request_body(**kwargs)
             async with Trace(
-                "http11.receive_response_headers", request, kwargs
+                "receive_response_headers", logger, request, kwargs
             ) as trace:
                 (
                     http_version,
@@ -111,7 +115,7 @@ async def handle_async_request(self, request: Request) -> Response:
                 },
             )
         except BaseException as exc:
-            async with Trace("http11.response_closed", request) as trace:
+            async with Trace("response_closed", logger, request) as trace:
                 await self._response_closed()
             raise exc
 
@@ -308,7 +312,7 @@ def __init__(self, connection: AsyncHTTP11Connection, request: Request) -> None:
     async def __aiter__(self) -> AsyncIterator[bytes]:
         kwargs = {"request": self._request}
         try:
-            async with Trace("http11.receive_response_body", self._request, kwargs):
+            async with Trace("receive_response_body", logger, self._request, kwargs):
                 async for chunk in self._connection._receive_response_body(**kwargs):
                     yield chunk
         except BaseException as exc:
@@ -321,5 +325,5 @@ async def __aiter__(self) -> AsyncIterator[bytes]:
     async def aclose(self) -> None:
         if not self._closed:
             self._closed = True
-            async with Trace("http11.response_closed", self._request):
+            async with Trace("response_closed", logger, self._request):
                 await self._connection._response_closed()

httpcore/_async/http2.py

@@ -1,4 +1,5 @@
 import enum
+import logging
 import time
 import types
 import typing
@@ -20,6 +21,8 @@
 from ..backends.base import AsyncNetworkStream
 from .interfaces import AsyncConnectionInterface
 
+logger = logging.getLogger("httpcore.http2")
+
 
 def has_body_headers(request: Request) -> bool:
     return any(
@@ -85,7 +88,7 @@ async def handle_async_request(self, request: Request) -> Response:
         async with self._init_lock:
             if not self._sent_connection_init:
                 kwargs = {"request": request}
-                async with Trace("http2.send_connection_init", request, kwargs):
+                async with Trace("send_connection_init", logger, request, kwargs):
                     await self._send_connection_init(**kwargs)
                 self._sent_connection_init = True
 
@@ -112,12 +115,12 @@ async def handle_async_request(self, request: Request) -> Response:
 
         try:
             kwargs = {"request": request, "stream_id": stream_id}
-            async with Trace("http2.send_request_headers", request, kwargs):
+            async with Trace("send_request_headers", logger, request, kwargs):
                 await self._send_request_headers(request=request, stream_id=stream_id)
-            async with Trace("http2.send_request_body", request, kwargs):
+            async with Trace("send_request_body", logger, request, kwargs):
                 await self._send_request_body(request=request, stream_id=stream_id)
             async with Trace(
-                "http2.receive_response_headers", request, kwargs
+                "receive_response_headers", logger, request, kwargs
             ) as trace:
                 status, headers = await self._receive_response(
                     request=request, stream_id=stream_id
@@ -132,7 +135,7 @@ async def handle_async_request(self, request: Request) -> Response:
             )
         except Exception as exc:  # noqa: PIE786
             kwargs = {"stream_id": stream_id}
-            async with Trace("http2.response_closed", request, kwargs):
+            async with Trace("response_closed", logger, request, kwargs):
                 await self._response_closed(stream_id=stream_id)
 
             if isinstance(exc, h2.exceptions.ProtocolError):
@@ -292,7 +295,7 @@ async def _receive_events(
                 for event in events:
                     if isinstance(event, h2.events.RemoteSettingsChanged):
                         async with Trace(
-                            "http2.receive_remote_settings", request
+                            "receive_remote_settings", logger, request
                         ) as trace:
                             await self._receive_remote_settings_change(event)
                             trace.return_value = event
@@ -491,7 +494,7 @@ def __init__(
     async def __aiter__(self) -> typing.AsyncIterator[bytes]:
         kwargs = {"request": self._request, "stream_id": self._stream_id}
         try:
-            async with Trace("http2.receive_response_body", self._request, kwargs):
+            async with Trace("receive_response_body", logger, self._request, kwargs):
                 async for chunk in self._connection._receive_response_body(
                     request=self._request, stream_id=self._stream_id
                 ):
@@ -507,5 +510,5 @@ async def aclose(self) -> None:
         if not self._closed:
             self._closed = True
             kwargs = {"stream_id": self._stream_id}
-            async with Trace("http2.response_closed", self._request, kwargs):
+            async with Trace("response_closed", logger, self._request, kwargs):
                 await self._connection._response_closed(stream_id=self._stream_id)

httpcore/_async/http_proxy.py

@@ -1,3 +1,4 @@
+import logging
 import ssl
 from base64 import b64encode
 from typing import List, Mapping, Optional, Sequence, Tuple, Union
@@ -25,6 +26,9 @@
 HeadersAsMapping = Mapping[Union[bytes, str], Union[bytes, str]]
 
 
+logger = logging.getLogger("httpcore.proxy")
+
+
 def merge_headers(
     default_headers: Optional[Sequence[Tuple[bytes, bytes]]] = None,
     override_headers: Optional[Sequence[Tuple[bytes, bytes]]] = None,
@@ -285,7 +289,7 @@ async def handle_async_request(self, request: Request) -> Response:
                     "server_hostname": self._remote_origin.host.decode("ascii"),
                     "timeout": timeout,
                 }
-                async with Trace("connection.start_tls", request, kwargs) as trace:
+                async with Trace("start_tls", logger, request, kwargs) as trace:
                     stream = await stream.start_tls(**kwargs)
                     trace.return_value = stream
 

httpcore/_async/socks_proxy.py

@@ -1,3 +1,4 @@
+import logging
 import ssl
 import typing
 
@@ -14,6 +15,9 @@
 from .http11 import AsyncHTTP11Connection
 from .interfaces import AsyncConnectionInterface
 
+logger = logging.getLogger("httpcore.socks")
+
+
 AUTH_METHODS = {
     b"\x00": "NO AUTHENTICATION REQUIRED",
     b"\x01": "GSSAPI",
@@ -223,7 +227,7 @@ async def handle_async_request(self, request: Request) -> Response:
                         "port": self._proxy_origin.port,
                         "timeout": timeout,
                     }
-                    with Trace("connection.connect_tcp", request, kwargs) as trace:
+                    with Trace("connect_tcp", logger, request, kwargs) as trace:
                         stream = await self._network_backend.connect_tcp(**kwargs)
                         trace.return_value = stream
 
@@ -235,7 +239,7 @@ async def handle_async_request(self, request: Request) -> Response:
                         "auth": self._proxy_auth,
                     }
                     with Trace(
-                        "connection.setup_socks5_connection", request, kwargs
+                        "setup_socks5_connection", logger, request, kwargs
                     ) as trace:
                         await _init_socks5_connection(**kwargs)
                         trace.return_value = stream
@@ -257,9 +261,7 @@ async def handle_async_request(self, request: Request) -> Response:
                             "server_hostname": self._remote_origin.host.decode("ascii"),
                             "timeout": timeout,
                         }
-                        async with Trace(
-                            "connection.start_tls", request, kwargs
-                        ) as trace:
+                        async with Trace("start_tls", logger, request, kwargs) as trace:
                             stream = await stream.start_tls(**kwargs)
                             trace.return_value = stream
 

httpcore/_sync/connection.py

@@ -1,4 +1,5 @@
 import itertools
+import logging
 import ssl
 from types import TracebackType
 from typing import Iterator, Optional, Type
@@ -16,6 +17,9 @@
 RETRIES_BACKOFF_FACTOR = 0.5  # 0s, 0.5s, 1s, 2s, 4s, etc.
 
 
+logger = logging.getLogger("httpcore.connection")
+
+
 def exponential_backoff(factor: float) -> Iterator[float]:
     yield 0
     for n in itertools.count(2):
@@ -105,9 +109,7 @@ def _connect(self, request: Request) -> NetworkStream:
                         "local_address": self._local_address,
                         "timeout": timeout,
                     }
-                    with Trace(
-                        "connection.connect_tcp", request, kwargs
-                    ) as trace:
+                    with Trace("connect_tcp", logger, request, kwargs) as trace:
                         stream = self._network_backend.connect_tcp(**kwargs)
                         trace.return_value = stream
                 else:
@@ -116,7 +118,7 @@ def _connect(self, request: Request) -> NetworkStream:
                         "timeout": timeout,
                     }
                     with Trace(
-                        "connection.connect_unix_socket", request, kwargs
+                        "connect_unix_socket", logger, request, kwargs
                     ) as trace:
                         stream = self._network_backend.connect_unix_socket(
                             **kwargs
@@ -137,7 +139,7 @@ def _connect(self, request: Request) -> NetworkStream:
                         "server_hostname": self._origin.host.decode("ascii"),
                         "timeout": timeout,
                     }
-                    with Trace("connection.start_tls", request, kwargs) as trace:
+                    with Trace("start_tls", logger, request, kwargs) as trace:
                         stream = stream.start_tls(**kwargs)
                         trace.return_value = stream
                 return stream
@@ -146,15 +148,15 @@ def _connect(self, request: Request) -> NetworkStream:
                     raise
                 retries_left -= 1
                 delay = next(delays)
-                # TRACE 'retry'
-                self._network_backend.sleep(delay)
+                with Trace("retry", logger, request, kwargs) as trace:
+                    self._network_backend.sleep(delay)
 
     def can_handle_request(self, origin: Origin) -> bool:
         return origin == self._origin
 
     def close(self) -> None:
         if self._connection is not None:
-            with Trace("connection.close", None, {}):
+            with Trace("close", logger, None, {}):
                 self._connection.close()
 
     def is_available(self) -> bool: