Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Fan out loggers #690

Merged
merged 5 commits into from
May 18, 2023
Merged

Fan out loggers #690

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
6f35e46
Fan out loggers
tomchristie May 18, 2023
7e31352
Merge branch 'master' into fan-logger-names
tomchristie May 18, 2023
db2c6c5
Updated CHANGELOG
tomchristie May 18, 2023
1974214
Merge branch 'fan-logger-names' of https://github.com/encode/httpcore…
tomchristie May 18, 2023
fca776b
Merge branch 'master' into fan-logger-names
tomchristie May 18, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions CHANGELOG.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,10 @@ All notable changes to this project will be documented in this file.

The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/).

## development

- Improve logging with per-module logger names. (#690)

## 0.17.1 (May 17th, 2023)

- If 'retries' is set, then allow retries if an SSL handshake error occurs. (#669)
Expand Down
32 changes: 16 additions & 16 deletions docs/logging.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
18 changes: 10 additions & 8 deletions httpcore/_async/connection.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
import itertools
import logging
import ssl
from types import TracebackType
from typing import Iterator, Optional, Type
Expand All @@ -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):
Expand Down Expand Up @@ -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:
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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:
Expand Down
16 changes: 10 additions & 6 deletions httpcore/_async/http11.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
import enum
import logging
import time
from types import TracebackType
from typing import (
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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,
Expand All @@ -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

Expand Down Expand Up @@ -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:
Expand All @@ -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()
19 changes: 11 additions & 8 deletions httpcore/_async/http2.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
import enum
import logging
import time
import types
import typing
Expand All @@ -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(
Expand Down Expand Up @@ -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

Expand All @@ -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
Expand All @@ -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):
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
):
Expand All @@ -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)
6 changes: 5 additions & 1 deletion httpcore/_async/http_proxy.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
import logging
import ssl
from base64 import b64encode
from typing import List, Mapping, Optional, Sequence, Tuple, Union
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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

Expand Down
12 changes: 7 additions & 5 deletions httpcore/_async/socks_proxy.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
import logging
import ssl
import typing

Expand All @@ -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",
Expand Down Expand Up @@ -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

Expand All @@ -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
Expand All @@ -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

Expand Down
18 changes: 10 additions & 8 deletions httpcore/_sync/connection.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
import itertools
import logging
import ssl
from types import TracebackType
from typing import Iterator, Optional, Type
Expand All @@ -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):
Expand Down Expand Up @@ -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:
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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:
Expand Down
Loading