Repository navigation
feat(httpclient): report request timing milestones #235
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
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -54,7 +54,7 @@ | |
| import warnings | ||
| import weakref | ||
| import zlib | ||
| from collections.abc import AsyncIterator, Iterator | ||
| from collections.abc import AsyncIterator, Callable, Iterator | ||
| from typing import IO, Any | ||
| from urllib.parse import quote, urlencode, urlparse | ||
|
|
||
|
|
@@ -130,6 +130,17 @@ | |
| # classes are captured here before that alias exists. | ||
| _TRANSPORT_TIMEOUTS = (socket.timeout, asyncio.TimeoutError) | ||
|
|
||
| # Called with a milestone name and the seconds elapsed since the request | ||
| # started, on a monotonic clock. Milestones are ``"request_started"``, | ||
| # ``"headers_received"`` and ``"body_complete"``. | ||
| TimingHook = Callable[[str, float], None] | ||
|
|
||
|
|
||
| def _emit_timing(on_timing: TimingHook | None, start: float, event: str) -> None: | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Two contract details are undocumented and both are observable from a caller:
|
||
| """Call *on_timing* with *event* and the elapsed seconds, if installed.""" | ||
| if on_timing is not None: | ||
| on_timing(event, time.perf_counter() - start) | ||
|
|
||
|
|
||
| # ── CaseInsensitiveDict ── | ||
|
|
||
|
|
@@ -683,6 +694,9 @@ class StreamingResponse: | |
| "_closed", | ||
| "_raw_set_cookies", | ||
| "_cookies", | ||
| "_on_timing", | ||
| "_timing_start", | ||
| "_timing_done", | ||
| ) | ||
|
|
||
| status_code: int | ||
|
|
@@ -701,6 +715,9 @@ class StreamingResponse: | |
| _closed: bool | ||
| _raw_set_cookies: list[str] | ||
| _cookies: dict[str, str] | None | ||
| _on_timing: TimingHook | None | ||
| _timing_start: float | ||
| _timing_done: bool | ||
|
|
||
| def __init__(self) -> None: | ||
| raise TypeError("Use _from_sync() or _from_async()") | ||
|
|
@@ -715,6 +732,8 @@ def _from_sync( | |
| conn: http.client.HTTPConnection, | ||
| content_encoding: str = "", | ||
| raw_set_cookies: list[str] | None = None, | ||
| on_timing: TimingHook | None = None, | ||
| timing_start: float = 0.0, | ||
| ) -> "StreamingResponse": | ||
| obj = object.__new__(cls) | ||
| obj.status_code = status_code | ||
|
|
@@ -735,6 +754,9 @@ def _from_sync( | |
| obj._closed = False | ||
| obj._raw_set_cookies = raw_set_cookies or [] | ||
| obj._cookies = None | ||
| obj._on_timing = on_timing | ||
| obj._timing_start = timing_start | ||
| obj._timing_done = False | ||
| return obj | ||
|
|
||
| @classmethod | ||
|
|
@@ -750,6 +772,8 @@ def _from_async( | |
| timeout: float, | ||
| content_encoding: str = "", | ||
| raw_set_cookies: list[str] | None = None, | ||
| on_timing: TimingHook | None = None, | ||
| timing_start: float = 0.0, | ||
| ) -> "StreamingResponse": | ||
| obj = object.__new__(cls) | ||
| obj.status_code = status_code | ||
|
|
@@ -770,8 +794,23 @@ def _from_async( | |
| obj._closed = False | ||
| obj._raw_set_cookies = raw_set_cookies or [] | ||
| obj._cookies = None | ||
| obj._on_timing = on_timing | ||
| obj._timing_start = timing_start | ||
| obj._timing_done = False | ||
| return obj | ||
|
|
||
| def _fire_body_complete(self) -> None: | ||
| """Report the ``body_complete`` milestone once, when a hook is set.""" | ||
| # Read defensively: a response built outside ``_from_sync`` / | ||
| # ``_from_async`` does not carry the timing attributes. | ||
| on_timing = getattr(self, "_on_timing", None) | ||
| if on_timing is None or getattr(self, "_timing_done", False): | ||
| return | ||
| self._timing_done = True | ||
| on_timing( | ||
| "body_complete", time.perf_counter() - getattr(self, "_timing_start", 0.0) | ||
| ) | ||
|
|
||
| @property | ||
| def ok(self) -> bool: | ||
| """True if status_code is 2xx.""" | ||
|
|
@@ -809,6 +848,7 @@ def iter_bytes(self, chunk_size: int = 4096) -> Iterator[bytes]: | |
| yield remaining | ||
| except (OSError, http.client.HTTPException) as exc: | ||
| raise HttpConnectionError(str(exc)) from exc | ||
| self._fire_body_complete() | ||
|
|
||
| def iter_lines(self) -> Iterator[str]: | ||
| """Yield response body line by line (decoded).""" | ||
|
|
@@ -854,6 +894,7 @@ async def aiter_bytes(self, chunk_size: int = 4096) -> AsyncIterator[bytes]: | |
| ) | ||
| except OSError as exc: | ||
| raise HttpConnectionError(str(exc)) from exc | ||
| self._fire_body_complete() | ||
|
|
||
| async def _select_raw_iterator(self, chunk_size: int) -> AsyncIterator[bytes]: | ||
| """Select and yield from the appropriate raw byte iterator.""" | ||
|
|
@@ -2160,6 +2201,8 @@ def _build_sync_response( | |
| conn: http.client.HTTPConnection, | ||
| stream: bool, | ||
| raw_set_cookies: list[str] | None = None, | ||
| on_timing: TimingHook | None = None, | ||
| timing_start: float = 0.0, | ||
| ) -> tuple[Response | StreamingResponse, bool]: | ||
| """Build a final sync response (streaming or buffered). | ||
|
|
||
|
|
@@ -2176,9 +2219,12 @@ def _build_sync_response( | |
| conn, | ||
| content_encoding=content_encoding, | ||
| raw_set_cookies=raw_set_cookies, | ||
| on_timing=on_timing, | ||
| timing_start=timing_start, | ||
| ), False | ||
|
|
||
| resp_body = resp.read() | ||
| _emit_timing(on_timing, timing_start, "body_complete") | ||
| if content_encoding: | ||
| resp_body = _decompress_body(resp_body, content_encoding) | ||
| return Response( | ||
|
|
@@ -2237,6 +2283,7 @@ def _sync_request( | |
| auth: tuple[str, str] | Auth | None = None, | ||
| proxy: str | None = None, | ||
| cookies: dict[str, str] | None = None, | ||
| on_timing: TimingHook | None = None, | ||
| _pool: _SyncConnectionPool | None = _DEFAULT_SYNC_POOL, | ||
| ) -> Response | StreamingResponse: | ||
| """Perform a synchronous HTTP request. | ||
|
|
@@ -2249,6 +2296,9 @@ def _sync_request( | |
| c. Handle redirects / digest auth / response construction | ||
| d. Connection lifecycle (pool release or close) | ||
| """ | ||
| timing_start = time.perf_counter() | ||
| if on_timing is not None: | ||
| on_timing("request_started", 0.0) | ||
| url, body, req_headers, auth_obj = _prepare_request( | ||
| method, url, headers, data, json, files, params, auth, cookies | ||
| ) | ||
|
|
@@ -2285,6 +2335,7 @@ def _sync_request( | |
| conn.request(method, request_path, body=body, headers=req_headers) | ||
| resp = conn.getresponse() | ||
| resp_version = resp.version | ||
| _emit_timing(on_timing, timing_start, "headers_received") | ||
| except (OSError, http.client.HTTPException) as exc: | ||
| # A timeout is not a stale connection: retrying would | ||
| # double the caller's wall-clock budget and could reach | ||
|
|
@@ -2352,6 +2403,8 @@ def _sync_request( | |
| conn, | ||
| stream, | ||
| raw_set_cookies=accumulated_set_cookies, | ||
| on_timing=on_timing, | ||
| timing_start=timing_start, | ||
| ) | ||
| completed = True | ||
| return result | ||
|
|
@@ -2748,6 +2801,8 @@ def _build_async_streaming_response( | |
| writer: asyncio.StreamWriter, | ||
| timeout: float, | ||
| raw_set_cookies: list[str] | None = None, | ||
| on_timing: TimingHook | None = None, | ||
| timing_start: float = 0.0, | ||
| ) -> StreamingResponse: | ||
| """Build an async StreamingResponse from response metadata.""" | ||
| content_encoding = resp_headers.get("content-encoding", "") | ||
|
|
@@ -2766,6 +2821,8 @@ def _build_async_streaming_response( | |
| timeout, | ||
| content_encoding=content_encoding, | ||
| raw_set_cookies=raw_set_cookies, | ||
| on_timing=on_timing, | ||
| timing_start=timing_start, | ||
| ) | ||
|
|
||
|
|
||
|
|
@@ -2788,6 +2845,7 @@ async def _async_request( | |
| auth: tuple[str, str] | Auth | None = None, | ||
| proxy: str | None = None, | ||
| cookies: dict[str, str] | None = None, | ||
| on_timing: TimingHook | None = None, | ||
| _pool: _AsyncConnectionPool | None = None, | ||
| ) -> Response | StreamingResponse: | ||
| """Perform an asynchronous HTTP request using asyncio streams. | ||
|
|
@@ -2800,6 +2858,9 @@ async def _async_request( | |
| c. Handle redirects / digest auth / response construction | ||
| d. Connection lifecycle (pool release or close) | ||
| """ | ||
| timing_start = time.perf_counter() | ||
| if on_timing is not None: | ||
| on_timing("request_started", 0.0) | ||
| url, body, req_headers, auth_obj = _prepare_request( | ||
| method, url, headers, data, json, files, params, auth, cookies | ||
| ) | ||
|
|
@@ -2843,6 +2904,7 @@ async def _async_request( | |
| iter_set_cookies, | ||
| resp_version, | ||
| ) = await _async_read_response_headers(reader, timeout) | ||
| _emit_timing(on_timing, timing_start, "headers_received") | ||
| except ( | ||
| OSError, | ||
| asyncio.IncompleteReadError, | ||
|
|
@@ -2909,10 +2971,13 @@ async def _async_request( | |
| writer, | ||
| timeout, | ||
| raw_set_cookies=accumulated_set_cookies, | ||
| on_timing=on_timing, | ||
| timing_start=timing_start, | ||
| ) | ||
|
|
||
| content_encoding = resp_headers.get("content-encoding", "") | ||
| resp_body = await _async_read_body(reader, resp_headers, timeout) | ||
| _emit_timing(on_timing, timing_start, "body_complete") | ||
| if content_encoding: | ||
| resp_body = _decompress_body(resp_body, content_encoding) | ||
| completed = True | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,161 @@ | ||
| """Tests for request timing milestones (zerodep#172).""" | ||
|
|
||
| from __future__ import annotations | ||
|
|
||
| import asyncio | ||
| import socketserver | ||
| import threading | ||
| import time | ||
|
|
||
| import pytest | ||
|
|
||
| import httpclient | ||
|
|
||
| HEADER_DELAY = 0.15 | ||
| BODY_DELAY = 0.15 | ||
|
|
||
|
|
||
| class _DelayedServer(socketserver.ThreadingTCPServer): | ||
| """HTTP/1.1 server that stalls before the headers and again mid-body.""" | ||
|
|
||
| daemon_threads = True | ||
| allow_reuse_address = True | ||
|
|
||
| def __init__(self): | ||
| super().__init__(("127.0.0.1", 0), _DelayedHandler) | ||
|
|
||
|
|
||
| class _DelayedHandler(socketserver.StreamRequestHandler): | ||
| def handle(self) -> None: | ||
| while True: | ||
| request_line = self.rfile.readline() | ||
| if not request_line: | ||
| return | ||
| while True: | ||
| header = self.rfile.readline() | ||
| if header in (b"\r\n", b"\n", b""): | ||
| break | ||
| time.sleep(HEADER_DELAY) | ||
| self.wfile.write( | ||
| b"HTTP/1.1 200 OK\r\n" | ||
| b"Content-Length: 2\r\n" | ||
| b"Content-Type: text/plain\r\n" | ||
| b"\r\n" | ||
| ) | ||
| self.wfile.flush() | ||
| time.sleep(BODY_DELAY) | ||
| self.wfile.write(b"hi") | ||
| self.wfile.flush() | ||
|
|
||
|
|
||
| @pytest.fixture | ||
| def delayed_url(): | ||
| server = _DelayedServer() | ||
| thread = threading.Thread(target=server.serve_forever, daemon=True) | ||
| thread.start() | ||
| host, port = server.server_address[:2] | ||
| try: | ||
| yield f"http://{host}:{port}/timing" | ||
| finally: | ||
| server.shutdown() | ||
| server.server_close() | ||
| thread.join(timeout=5) | ||
|
|
||
|
|
||
| def test_non_streaming_reports_three_milestones(delayed_url): | ||
| events: list[tuple[str, float]] = [] | ||
| response = httpclient.get( | ||
| delayed_url, on_timing=lambda event, elapsed: events.append((event, elapsed)) | ||
| ) | ||
|
|
||
| assert response.status_code == 200 | ||
| assert [name for name, _ in events] == [ | ||
| "request_started", | ||
| "headers_received", | ||
| "body_complete", | ||
| ] | ||
| names = [elapsed for _, elapsed in events] | ||
| assert names[0] == 0.0 | ||
| assert names[1] >= HEADER_DELAY * 0.6 | ||
| assert names[2] >= names[1] + BODY_DELAY * 0.6 | ||
|
|
||
|
|
||
| def test_streaming_body_complete_waits_for_the_read(delayed_url): | ||
| events: list[tuple[str, float]] = [] | ||
| response = httpclient.get( | ||
| delayed_url, | ||
| stream=True, | ||
| on_timing=lambda event, elapsed: events.append((event, elapsed)), | ||
| ) | ||
| assert [name for name, _ in events] == ["request_started", "headers_received"] | ||
|
|
||
| # The body is still arriving; nothing is reported until it is consumed. | ||
| time.sleep(BODY_DELAY * 2) | ||
| assert [name for name, _ in events] == ["request_started", "headers_received"] | ||
|
|
||
| assert response.read() == b"hi" | ||
| response.close() | ||
| assert [name for name, _ in events] == [ | ||
| "request_started", | ||
| "headers_received", | ||
| "body_complete", | ||
| ] | ||
|
|
||
|
|
||
| def test_streaming_reports_body_complete_once(delayed_url): | ||
| events: list[str] = [] | ||
| response = httpclient.get( | ||
| delayed_url, | ||
| stream=True, | ||
| on_timing=lambda event, _elapsed: events.append(event), | ||
| ) | ||
| response.read() | ||
| response.read() | ||
| response.close() | ||
| assert events.count("body_complete") == 1 | ||
|
|
||
|
|
||
| def test_no_hook_is_allowed(delayed_url): | ||
| response = httpclient.get(delayed_url) | ||
| assert response.status_code == 200 | ||
| assert response.content == b"hi" | ||
|
|
||
|
|
||
| def test_async_non_streaming_reports_three_milestones(delayed_url): | ||
| events: list[tuple[str, float]] = [] | ||
|
|
||
| async def run(): | ||
| return await httpclient.async_get( | ||
| delayed_url, | ||
| on_timing=lambda event, elapsed: events.append((event, elapsed)), | ||
| ) | ||
|
|
||
| response = asyncio.run(run()) | ||
| assert response.status_code == 200 | ||
| assert [name for name, _ in events] == [ | ||
| "request_started", | ||
| "headers_received", | ||
| "body_complete", | ||
| ] | ||
| assert events[1][1] >= HEADER_DELAY * 0.6 | ||
| assert events[2][1] >= events[1][1] + BODY_DELAY * 0.6 | ||
|
|
||
|
|
||
| def test_async_streaming_body_complete_waits_for_the_read(delayed_url): | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. The suite covers the module helpers only, while the docs promise the same for
|
||
| events: list[str] = [] | ||
|
|
||
| async def run(): | ||
| response = await httpclient.async_get( | ||
| delayed_url, | ||
| stream=True, | ||
| on_timing=lambda event, _elapsed: events.append(event), | ||
| ) | ||
| before = list(events) | ||
| body = await response.aread() | ||
| response.close() | ||
| return before, body | ||
|
|
||
| before, body = asyncio.run(run()) | ||
| assert before == ["request_started", "headers_received"] | ||
| assert body == b"hi" | ||
| assert events == ["request_started", "headers_received", "body_complete"] | ||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
TimingHookis the one new public name that is not in__all__, whileAuth,Response,StreamingResponse,Clientand the exception classes are. A caller annotatingdef hook(event: str, elapsed: float) -> Nonedoes not need it, but anyone writingon_timing: httpclient.TimingHookand running a linter that respects__all__gets flagged for importing a name the module does not advertise.