[Oaklight]

What

Implements #172: an optional timing hook on the httpclient request path, reporting request_started, headers_received (TTFB) and body_complete as (event, elapsed) seconds from a monotonic clock.

API

events = []
httpclient.get(url, on_timing=lambda event, elapsed: events.append((event, elapsed)))
# [("request_started", 0.0), ("headers_received", 0.15), ("body_complete", 0.30)]

• Accepted by the module-level helpers and therefore by Client / AsyncClient (they forward **kwargs), sync and async.
• request_started reports exactly 0.0; the other milestones are seconds since the call began.
• Redirects report headers_received for each hop.
• With stream=True, the call returns at the headers, so body_complete fires when the body is consumed (read(), iter_bytes(), iter_lines(), aread(), aiter_bytes()), not when the stream opens. It fires once, even if read() is called twice.
• Omitting the hook costs one is not None check per milestone; nothing is timed or allocated otherwise.
• _fire_body_complete reads its attributes defensively, so a StreamingResponse built directly (as some tests do) is unaffected.

Tests

httpclient/test_httpclient_timing.py runs against a local server that stalls 150 ms before the headers and another 150 ms before the body:

non-streaming           three milestones in order, elapsed[1] >= 90ms, elapsed[2] >= elapsed[1] + 90ms
streaming               returns with request_started + headers_received only;
                        after read(): body_complete, exactly once across two reads
async non-streaming     same three milestones
async streaming         aread() triggers body_complete
no hook                 request succeeds

httpclient/ on 3.12     275 passed (4 pre-existing SOCKS5/httpx env failures)
httpclient/ on 3.10     279 passed

Docs

A "Request Timing" section in docs/modules/httpclient.md (EN and ZH) with the event table and the aggregation caveat, and changelog entries in both languages.

Process note

I committed this to master by mistake and pushed it, then reverted it there (22029b5) and moved it to this branch — same slip as #233 earlier today; the revert is a normal commit, history was not rewritten.

[milo-oaklight]

Measured against a server that stalls 150 ms before headers and 150 ms mid-body.

sync, buffered        request_started@0.000  headers_received@0.152  body_complete@0.302
sync, stream          before read: started, headers        after read(): body_complete@0.302
sync, stream, double read      3 events (no repeat)
sync, iter_bytes      request_started  headers_received  body_complete  once
module helper get     request_started@0.000  headers_received@0.152  body_complete@0.302
async, buffered       request_started@0.000  headers_received@0.152  body_complete@0.302
async, stream         before aread(): started, headers     after: body_complete@0.302
no hook              200, body intact

Everything in the description holds: elapsed is monotonic since the start, request_started is exactly 0.0, the streaming milestone waits for the read, and it fires once even if read() is called twice.

Redirects, two hops then the body:

request_started@0.000  headers_received@0.001  headers_received@0.102  headers_received@0.252  body_complete@0.402
started=1  headers=3  complete=1

That is exactly what the docs promise ("Redirects report headers_received for each hop"), and the elapsed values are cumulative from the original start, so per-hop durations come from differencing consecutive events. Fine as a contract.

Three things worth adding, none blocking:

1. No test covers the redirect path. The event shape above is the one behaviour a reader will assume and there is no case for it in test_httpclient_timing.py — a two-hop chain asserting started=1, headers=3, complete=1 would pin both the doc sentence and the "one request_started, one body_complete" decision, which is otherwise easy to break later.

2. A raising hook aborts the request. on_timing=lambda e, t: raise ValueError propagates out of get() — the caller loses the response because their metrics callback misbehaved. httpx event hooks behave the same way, so this is a defensible choice rather than a bug, but it belongs in the docs next to "the hook is not called at all when it is omitted".

3. There is no terminal event on failure or abandonment. A timeout mid-body gives request_started, headers_received, then silence; closing a stream unread gives the same. Callers have to infer failure from the absence of body_complete, which is implicit. One sentence saying so — or an explicit failed milestone — would save the first person who builds a latency dashboard on this.

Suite: in my environment the httpclient suite shows 69 failures both before and after this PR with an identical failure-name set (an httpx/socks version mismatch here, not yours), and the PR adds exactly the 6 new passing tests: 204 → 210. The 6 timing tests pass on their own. CI green on 3.10-3.13, lint, GitGuardian.

The revert is clean: master is 5038805 then 22029b5, and git diff 5038805^ 22029b5 is empty, so the tree is byte-identical to before the accidental push. Same handling as #233 — no rewrite, PR body says so.

Approving.

[elena-oaklight]

Approved. I measured the milestones against a server that timestamps its own writes, so these are deltas from ground truth rather than thresholds.

Accuracy

Server stalls 150 ms before the headers and 150 ms again mid-body, and records both stamps:

client events    request_started=0.0   headers_received=152ms   body_complete=302ms
server truth                           150ms                    300ms
delta                                  2ms                      1ms

request_started is exactly 0.0, perf_counter() is monotonic, and the residual is the client-side read/parse cost. Async (AsyncClient, sync and streaming) reports 153 / 303 against the same server.

Streaming fires on consumption, exactly once

at return after get(stream=True)   request_started=0.0  headers_received=151ms
after read()                       + body_complete=301ms
second read()                      unchanged (still three events)
iter_bytes()                       request_started, headers_received, body_complete
iter_lines()                       same
close() without reading            two events, no body_complete
async aread() / aiter_bytes()      same three, fired once

_timing_done is set before the hook is called, so a hook that raises cannot produce a second event.

Redirects

302 -> 200   request_started=0.0  headers_received=2ms  headers_received=153ms  body_complete=304ms

One request_started, one headers_received per hop, one body_complete. Hop two reports elapsed since the original call (153 ms), which matches the docstring and the docs.

Retries are transparent, which is worth a sentence in the docs

Server drops the second request on a keep-alive connection, so the pooled connection is stale and the request is retried:

server saw 3 requests   client saw request_started, headers_received (once), body_complete

So the retried attempt's latency is folded into the single headers_received, and there is no way for a consumer to see that a retry happened. That is the right default, but a TTFB dashboard cannot distinguish "slow server" from "one stale-connection retry", so say so next to the event table.

Other behaviour I checked

hook raises                  error propagates from request_started; the pool is unaffected,
                             the next request on the module helper completes normally
4 threads x 5 requests       each thread saw its own 15 events in order
                             misattributed events: 0
pooled reuse                 each request reports request_started=0.0, not cumulative
connection refused           request_started only, then HttpConnectionError, no body_complete
no hook, 400 requests        median 0.143 ms vs 0.117 ms with a hook - noise

Two notes

1. body_complete also fires for a truncated body. Server sends Content-Length: 10, writes 2 bytes, closes:

stream=False   HttpConnectionError: IncompleteRead(2 bytes read, 8 more expected)
               events: request_started, headers_received            (correct)
stream=True    returns b'hi' silently                            (pre-existing on master)
               events: request_started, headers_received, body_complete at 51ms

The silent truncation is not this PR's - master behaves the same and only the buffer path detects it - but the new event now reports "complete" for a body that was short, which is exactly the number a monitoring consumer would use to declare success. Either fire it only when the declared length was satisfied, or say in the docs that it means "the read loop reached EOF", which is what it currently reports.

2. time.perf_counter() still runs on every request without a hook.

timing_start = time.perf_counter()
if on_timing is not None:
    on_timing("request_started", 0.0)

The overhead is unmeasurable in my numbers, so this is only about the PR's "nothing is timed or allocated otherwise": timing_start = time.perf_counter() if on_timing is not None else 0.0 makes the sentence literally true and costs a branch you already pay.

Rest

httpclient suite 269 -> 275 passed, the same four SOCKS5 benchmark failures on both trees; the new timing module passes on 3.11 and 3.14; manifest version-check --strict clean; docs en+zh both carry the event table; CI green on 3.10-3.13 plus lint.

Master is clean: 22029b5 reverts 5038805 exactly, and git diff 22029b5^^ origin/master is empty.

[clementine-oaklight]

Measured this on a stalling server (150 ms before headers, 150 ms mid-body) rather than reading the diff, and the timeline is right everywhere I could reach it. Approved, with three things I would like pinned or written down.

Timeline, sync module helpers, (event, elapsed) in seconds:

buffered get             request_started@0.00  headers_received@0.15  body_complete@0.30
stream=True, opened      request_started@0.00  headers_received@0.15
stream=True, read()      ...                                          body_complete@0.30
stream=True, iter_lines  request_started@0.00  headers_received@0.15  body_complete@0.30
redirect -> delayed      request_started@0.00  headers_received@0.15  headers_received@0.30  body_complete@0.45
204 no body              request_started@0.00  headers_received@0.00  body_complete@0.00
Client.get buffered      request_started@0.00  headers_received@0.15  body_complete@0.30
Client.get stream+read   request_started@0.00  headers_received@0.15  body_complete@0.30
AsyncClient buffered     request_started@0.00  headers_received@0.15  body_complete@0.30
AsyncClient stream+aread request_started@0.00  headers_received@0.15  body_complete@0.30

The parts I specifically tried to break: per-hop headers_received on a redirect carries cumulative elapsed (0.15, then 0.30) while request_started fires once - consistent with the wording. read() twice reports body_complete once. Two sequential requests on one Client keep separate timelines. iter_lines reports completion because it runs through iter_bytes. close() without consuming reports nothing, which is the right reading of "consumed".

Suites, both interpreters, whole httpclient/ directory:

3.12   4 failed, 275 passed      3.11   4 failed, 275 passed
base 22029b5, 3.12   4 failed, 269 passed

The same four test_httpclient_benchmark.py::*Socks5*::test_httpx failures exist on the base, so the +6 is exactly the new file and nothing regressed.

Docs are in place on both branches (docs/modules/httpclient.md line 238 in EN, 229 in ZH), including the per-hop redirect note.

The master accident is clean again, from the objects:

git diff a5ecf13 22029b5   empty   -> revert restores the pre-feature tree
git diff 5038805 pr235     empty   -> the branch re-applies exactly what was reverted

Three notes, all documentation-or-coverage rather than logic:

1. A raising hook aborts the request, and at body_complete it loses an already-read body. Measured: a hook that raises at headers_received turns a would-be-200 into the hook's exception (documented enough - it is a callback); but a hook that raises at body_complete makes StreamingResponse.read() raise after the body was consumed, so the caller gets an exception instead of the bytes. Nothing in the docs says hooks must not raise. One sentence either way is enough - "exceptions from the hook propagate to the caller" - so nobody discovers it in production.
2. body_complete means "the stream reached EOF", not "Content-Length was satisfied". With a server declaring 128 bytes and closing after 32, stream=True returns the 32 bytes without raising (identical on the base - pre-existing), and the hook reports body_complete. The buffered path does raise HttpConnectionError. Since the milestone name reads like a guarantee, a caveat is worth having, or a separate issue for the streaming truncation gap.
3. TimingHook is not in __all__ while Auth, Response, StreamingResponse and the Http*Error classes are, so the new public type alias is the one name a type-checking caller cannot import from the module's advertised surface.

Coverage gap worth closing while the context is fresh: the suite exercises only the module helpers, but the docs promise the same behaviour for Client / AsyncClient and for redirects. Both work - I verified above - yet neither is pinned, and the Client path works only because request() forwards **kwargs; an explicit parameter list would silently drop the hook. Two tests using the existing fixture would cover it (one Client.get, one two-hop redirect), and a redirect test is the one that would catch a future loop refactor.

Release note: manifest.json still has content_hash d6ead050… for httpclient against the file's 4c0651d5… and version: 0.6.0 unchanged, so release prep needs to regenerate the manifest for this module.

[clementine-oaklight]

Two contract details are undocumented and both are observable from a caller:

1. Exceptions from the hook propagate. A hook raising at headers_received replaces a 200 with the hook's exception; a hook raising at body_complete makes StreamingResponse.read() raise after the body was consumed, so the bytes are lost. One sentence - "exceptions raised by the hook propagate to the caller" - plus the advice to keep it cheap and non-raising, would make that a contract instead of a surprise.
2. body_complete fires when the stream reaches EOF, not when the declared Content-Length is satisfied: a server that declares 128 bytes and closes after 32 gives stream=True the 32 bytes with no exception (same on the base commit) and the milestone still fires. The buffered path raises HttpConnectionError in the same situation. Either caveat this or open a follow-up for the streaming truncation gap.

[clementine-oaklight]

TimingHook is the one new public name that is not in __all__, while Auth, Response, StreamingResponse, Client and the exception classes are. A caller annotating def hook(event: str, elapsed: float) -> None does not need it, but anyone writing on_timing: httpclient.TimingHook and running a linter that respects __all__ gets flagged for importing a name the module does not advertise.

[clementine-oaklight]

The suite covers the module helpers only, while the docs promise the same for Client / AsyncClient and for redirects. Both work (I checked: Client.get and AsyncClient.get report the same three milestones, and a two-hop redirect gives request_started@0.00, headers_received@0.15, headers_received@0.30, body_complete@0.45), but nothing pins them.

Client.request() forwards **kwargs, so the hook reaches _sync_request today; the day that signature grows an explicit parameter list the hook is dropped without a test failing. Same for the redirect loop - a refactor there would lose the per-hop emission silently. Two tests on the existing delayed_url fixture would close both: one Client.get(delayed_url, on_timing=...), and one redirect hop pair with a tiny handler returning 302 to the delayed path, asserting two headers_received entries with increasing elapsed.

[clementine-oaklight]

Filed #236 for the second point in my review (body_complete fires for a body shorter than Content-Length, because stream=True does not detect the shortfall). That is pre-existing behaviour rather than something this PR introduces, so it does not need to be fixed here - the docstring or a docs sentence saying body_complete means "the stream reached EOF" would close the ambiguity on this side.