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.

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

Add DEBUG level logging. #648

Merged
merged 7 commits into from
Mar 16, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
41 changes: 41 additions & 0 deletions docs/logging.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,41 @@
# Logging

If you need to inspect the internal behaviour of `httpcore`, you can use Python's standard logging to output debug level information.

For example, the following configuration...

```python
import logging
import httpcore

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

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
```

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.
3 changes: 2 additions & 1 deletion httpcore/_async/connection.py
Original file line number Diff line number Diff line change
Expand Up @@ -156,7 +156,8 @@ def can_handle_request(self, origin: Origin) -> bool:

async def aclose(self) -> None:
if self._connection is not None:
await self._connection.aclose()
async with Trace("connection.close", None, {}):
await self._connection.aclose()

def is_available(self) -> bool:
if self._connection is None:
Expand Down
3 changes: 2 additions & 1 deletion httpcore/_sync/connection.py
Original file line number Diff line number Diff line change
Expand Up @@ -156,7 +156,8 @@ def can_handle_request(self, origin: Origin) -> bool:

def close(self) -> None:
if self._connection is not None:
self._connection.close()
with Trace("connection.close", None, {}):
self._connection.close()

def is_available(self) -> bool:
if self._connection is None:
Expand Down
52 changes: 43 additions & 9 deletions httpcore/_trace.py
Original file line number Diff line number Diff line change
@@ -1,20 +1,42 @@
import logging
from types import TracebackType
from typing import Any, Dict, Optional, Type

from ._models import Request

logger = logging.getLogger("httpcore")


class Trace:
def __init__(
self, name: str, request: Request, kwargs: Optional[Dict[str, Any]] = None
self,
name: str,
request: Optional[Request] = None,
kwargs: Optional[Dict[str, Any]] = None,
) -> None:
self.name = name
self.trace = request.extensions.get("trace")
self.trace_extension = (
None if request is None else request.extensions.get("trace")
)
self.debug = logger.isEnabledFor(logging.DEBUG)
self.kwargs = kwargs or {}
self.return_value: Any = None
self.should_trace = self.debug or self.trace_extension is not None

def trace(self, name: str, info: Dict[str, Any]) -> None:
if self.trace_extension is not None:
self.trace_extension(name, info)

if self.debug:
if not info or "return_value" in info and info["return_value"] is None:
message = name
else:
args = " ".join([f"{key}={value!r}" for key, value in info.items()])
message = f"{name} {args}"
logger.debug(message)

def __enter__(self) -> "Trace":
if self.trace is not None:
if self.should_trace:
info = self.kwargs
self.trace(f"{self.name}.started", info)
return self
Expand All @@ -25,18 +47,30 @@ def __exit__(
exc_value: Optional[BaseException] = None,
traceback: Optional[TracebackType] = None,
) -> None:
if self.trace is not None:
if self.should_trace:
if exc_value is None:
info = {"return_value": self.return_value}
self.trace(f"{self.name}.complete", info)
else:
info = {"exception": exc_value}
self.trace(f"{self.name}.failed", info)

async def atrace(self, name: str, info: Dict[str, Any]) -> None:
if self.trace_extension is not None:
await self.trace_extension(name, info)

if self.debug:
if not info or "return_value" in info and info["return_value"] is None:
message = name
else:
args = " ".join([f"{key}={value!r}" for key, value in info.items()])
message = f"{name} {args}"
logger.debug(message)

async def __aenter__(self) -> "Trace":
if self.trace is not None:
if self.should_trace:
info = self.kwargs
await self.trace(f"{self.name}.started", info)
await self.atrace(f"{self.name}.started", info)
return self

async def __aexit__(
Expand All @@ -45,10 +79,10 @@ async def __aexit__(
exc_value: Optional[BaseException] = None,
traceback: Optional[TracebackType] = None,
) -> None:
if self.trace is not None:
if self.should_trace:
if exc_value is None:
info = {"return_value": self.return_value}
await self.trace(f"{self.name}.complete", info)
await self.atrace(f"{self.name}.complete", info)
else:
info = {"exception": exc_value}
await self.trace(f"{self.name}.failed", info)
await self.atrace(f"{self.name}.failed", info)
6 changes: 6 additions & 0 deletions httpcore/backends/mock.py
Original file line number Diff line number Diff line change
Expand Up @@ -44,6 +44,9 @@ def start_tls(
def get_extra_info(self, info: str) -> typing.Any:
return MockSSLObject(http2=self._http2) if info == "ssl_object" else None

def __repr__(self) -> str:
return "<httpcore.MockStream>"


class MockBackend(NetworkBackend):
def __init__(self, buffer: typing.List[bytes], http2: bool = False) -> None:
Expand Down Expand Up @@ -98,6 +101,9 @@ async def start_tls(
def get_extra_info(self, info: str) -> typing.Any:
return MockSSLObject(http2=self._http2) if info == "ssl_object" else None

def __repr__(self) -> str:
return "<httpcore.AsyncMockStream>"


class AsyncMockBackend(AsyncNetworkBackend):
def __init__(self, buffer: typing.List[bytes], http2: bool = False) -> None:
Expand Down
1 change: 1 addition & 0 deletions mkdocs.yml
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@ nav:
- HTTP/2: 'http2.md'
- Async Support: 'async.md'
- Extensions: 'extensions.md'
- Logging: 'logging.md'
- Exceptions: 'exceptions.md'

theme:
Expand Down
69 changes: 69 additions & 0 deletions tests/_async/test_connection_pool.py
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
import logging
from typing import List, Optional

import pytest
Expand Down Expand Up @@ -160,6 +161,74 @@ async def trace(name, kwargs):
]


@pytest.mark.anyio
async def test_debug_request(caplog):
"""
The 'trace' request extension allows for a callback function to inspect the
internal events that occur while sending a request.
"""
caplog.set_level(logging.DEBUG)

network_backend = AsyncMockBackend(
[
b"HTTP/1.1 200 OK\r\n",
b"Content-Type: plain/text\r\n",
b"Content-Length: 13\r\n",
b"\r\n",
b"Hello, world!",
]
)

async with AsyncConnectionPool(network_backend=network_backend) as pool:
await pool.request("GET", "http://example.com/")

assert caplog.record_tuples == [
(
"httpcore",
logging.DEBUG,
"connection.connect_tcp.started host='example.com' port=80 local_address=None timeout=None",
),
(
"httpcore",
logging.DEBUG,
"connection.connect_tcp.complete return_value=<httpcore.AsyncMockStream>",
),
(
"httpcore",
logging.DEBUG,
"http11.send_request_headers.started request=<Request [b'GET']>",
),
("httpcore", logging.DEBUG, "http11.send_request_headers.complete"),
(
"httpcore",
logging.DEBUG,
"http11.send_request_body.started request=<Request [b'GET']>",
),
("httpcore", logging.DEBUG, "http11.send_request_body.complete"),
(
"httpcore",
logging.DEBUG,
"http11.receive_response_headers.started request=<Request [b'GET']>",
),
(
"httpcore",
logging.DEBUG,
"http11.receive_response_headers.complete return_value="
"(b'HTTP/1.1', 200, b'OK', [(b'Content-Type', b'plain/text'), (b'Content-Length', b'13')])",
),
(
"httpcore",
logging.DEBUG,
"http11.receive_response_body.started request=<Request [b'GET']>",
),
("httpcore", logging.DEBUG, "http11.receive_response_body.complete"),
("httpcore", logging.DEBUG, "http11.response_closed.started"),
("httpcore", logging.DEBUG, "http11.response_closed.complete"),
("httpcore", logging.DEBUG, "connection.close.started"),
("httpcore", logging.DEBUG, "connection.close.complete"),
]


@pytest.mark.anyio
async def test_connection_pool_with_http_exception():
"""
Expand Down
69 changes: 69 additions & 0 deletions tests/_sync/test_connection_pool.py
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
import logging
from typing import List, Optional

import pytest
Expand Down Expand Up @@ -161,6 +162,74 @@ def trace(name, kwargs):



def test_debug_request(caplog):
"""
The 'trace' request extension allows for a callback function to inspect the
internal events that occur while sending a request.
"""
caplog.set_level(logging.DEBUG)

network_backend = MockBackend(
[
b"HTTP/1.1 200 OK\r\n",
b"Content-Type: plain/text\r\n",
b"Content-Length: 13\r\n",
b"\r\n",
b"Hello, world!",
]
)

with ConnectionPool(network_backend=network_backend) as pool:
pool.request("GET", "http://example.com/")

assert caplog.record_tuples == [
(
"httpcore",
logging.DEBUG,
"connection.connect_tcp.started host='example.com' port=80 local_address=None timeout=None",
),
(
"httpcore",
logging.DEBUG,
"connection.connect_tcp.complete return_value=<httpcore.MockStream>",
),
(
"httpcore",
logging.DEBUG,
"http11.send_request_headers.started request=<Request [b'GET']>",
),
("httpcore", logging.DEBUG, "http11.send_request_headers.complete"),
(
"httpcore",
logging.DEBUG,
"http11.send_request_body.started request=<Request [b'GET']>",
),
("httpcore", logging.DEBUG, "http11.send_request_body.complete"),
(
"httpcore",
logging.DEBUG,
"http11.receive_response_headers.started request=<Request [b'GET']>",
),
(
"httpcore",
logging.DEBUG,
"http11.receive_response_headers.complete return_value="
"(b'HTTP/1.1', 200, b'OK', [(b'Content-Type', b'plain/text'), (b'Content-Length', b'13')])",
),
(
"httpcore",
logging.DEBUG,
"http11.receive_response_body.started request=<Request [b'GET']>",
),
("httpcore", logging.DEBUG, "http11.receive_response_body.complete"),
("httpcore", logging.DEBUG, "http11.response_closed.started"),
("httpcore", logging.DEBUG, "http11.response_closed.complete"),
("httpcore", logging.DEBUG, "connection.close.started"),
("httpcore", logging.DEBUG, "connection.close.complete"),
]



def test_connection_pool_with_http_exception():
"""
HTTP/1.1 requests that result in an exception during the connection should
Expand Down