Add request phase timing: Server-Timing subtimings and access telemetry - #1074
Add request phase timing: Server-Timing subtimings and access telemetry#1074jevansnyc wants to merge 20 commits into
Conversation
* Add request phase timing design spec (Server-Timing subtimings + access telemetry) * Address review round 1: freeze point, template-cache naming, snapshot semantics, KV scope, geo carry, route template, sink confirmation, sampling and query model, config rollback * Address review round 2: auction-wait placement modes, conservative private-only header emission, non-null sorting key with service identity, coarse publisher route template, telemetry snapshot and outage behavior, tinybird flag decoupling, adapter phase semantics * Add request phase timing implementation plan * Address engineer review: KV timing decorator, try_lock sampling, route metadata extension, adapter-derived env, typed template-cache state, adapter-owned emission context, per-mode delivery semantics, Axum outer wrapper
…ite-back in middleware Three final-review fixes for access telemetry correctness: - Normalize the HTTP method to an allowlist (GET/HEAD/POST/PUT/DELETE/ PATCH/OPTIONS, else "other") inside access_event_row, so a client- controlled extension-method token can never inflate the LowCardinality method column, regardless of which adapter builds the row. - Guard emit_access_telemetry_after_send against snapshots carrying a degraded sample_rate of 0.0 (captured on the app-state-build-failure fallback path), which could otherwise be sampled in by freshly reloaded settings and corrupt the sum(1.0/sample_rate) volume estimator. - Mirror the geo lookup write-back from apply_entry_point_finalize_headers into FinalizeResponseMiddleware::handle, so a middleware-finalized response that resolved geo via fallback carries the resolved GeoLookupState for the access-telemetry snapshot instead of showing country "unknown".
|
Post-review addition from the first live full-stack test (stackpop.com staging property): commit 7cf7d86 adds JSONPaths to every access_logs_raw column and replaces the event_date DEFAULT column with a toDate(event_ts) sorting-key expression. The Events API rejects NDJSON ingestion into a datasource without JSONPaths (400, discovered live; the confirmed-delivery check surfaced it via the drop warning), and once any column has a path every column needs one, which a DEFAULT column the producer never sends cannot satisfy. Spec section 9 updated in the same commit. Verified end to end: rows now flowing guest -> Events API -> ClickHouse with correct phase attribution and route-template normalization. |
prk-Jr
left a comment
prk-Jr
left a comment
There was a problem hiding this comment.
Review summary
Verdict: Request changes.
The timing core is careful, well-reasoned work, and the Tinybird schema discipline is actually better than the PR body claims (verified below). The blocker is that this ships a reproducible crash-on-every-request regression on the Cloudflare adapter — with a one-line fix — plus a second instance of the same bug that CI structurally cannot catch, and a route normalizer that lets UUIDs, reset tokens and article slugs into a 30-day dataset.
Verification performed
Reviewed at head 7cf7d867 in a scratch worktree. Local gates, all run there:
| Gate | Result |
|---|---|
cargo fmt --all -- --check |
PASS |
cargo clippy-fastly / clippy-axum / clippy-cloudflare-wasm |
PASS |
cargo test-fastly |
PASS (2235 + 186 + 21 + 4 + 2) |
cargo test-axum |
PASS (25 + 14 + 1) |
npx vitest run |
PASS — 45 files, 871 tests, 0 failures |
gh pr checks 1074: 19 checks, 1 failing — integration tests. It is not in the branch-protection required set, so it will not block the merge button, but it is a genuine regression (root-caused inline).
Blocking
- CRITICAL —
std::time::Instantpanics onwasm32-unknown-unknown; every publisher request on Cloudflare traps. Confirmed by reproducing the failing integration test locally, capturing the workerd stack trace, applying the fix, and re-running green (15.34s fail → 1.16s pass). - HIGH — Two more
Instant::now()calls on the auction path inpublisher.rs. The integration fixture has[auction] enabled = false, so CI stays green even after finding 1 is fixed, while Cloudflare does dispatch auctions in production. - HIGH —
publisher_route_templateadmits UUIDs, opaque tokens and full article slugs into a 30-day dataset, contradicting the module's own doc comment.
Verified praise
- Schema alignment is exactly right. Parsed all four artifacts: 26 datasource columns, 26 producer keys, 26 fixture keys, 26
FORWARD_QUERYcolumns — identical names and identical order, zero set difference. try_lock-only is real. 7 lock acquisitions inrequest_timing.rs, alltry_lock, zero.lock(). No method calls another while holding its guard, so no re-entrant self-deadlock.- Saturating arithmetic is complete —
saturating_addinrecord/record_auction_wait/CountingWriter::write,try_from(..).unwrap_or(MAX)in bothduration_msandrecord_buffered_delivery. - The Server-Timing cache-control gate holds on every emit path. Both emitters funnel through
append_server_timing_if_private, andcache_control_value_has_directiveis exact-name and quote-aware (not-private/no-storeycorrectly do not match). On Fastly the call sits afterapply_terminal_response_effectsand both finalize passes, soCache-Controlis settled and nothing mutates it afterwards. [observability]back-compat is sound.Settingscarriesdeny_unknown_fieldsand the pushed blob is a serde serialization ofSettings, soskip_serializing_if = "ObservabilitySettings::is_default"genuinely keeps a default table out of the blob.TinybirdSettingshas nodeny_unknown_fieldson either side, so the newauction_enabledkey does not break rollback either.- The hand-rolled Axum
serveis behaviourally equivalent to the upstream helper it replaces (Stores::default()makes every store-attach branch a no-op; the rest is mirrored exactly).
Audit of the PR body's stated limitations
Most disclosures check out. Four do not:
| Disclosure | Verdict |
|---|---|
| "The 27 vitest failures ... will block the JS CI gate" | Stale. vitest is green on CI; locally 871 tests, 0 failures. |
| "Cloudflare and Spin collect but do not emit in v1" | Badly understated. Spin is fine (wasm32-wasip1, std Instant works). Cloudflare does not collect — it traps on every publisher request. |
"sorting key (event_date, service_id, ...)" |
Inaccurate. Actual key is toDate(event_ts), service_id, ...; event_date is not a column at all. |
| Failing Cloudflare integration job | Unmentioned, and failing on all three runs of the branch. |
Accurate as written: deploy/rollback ordering and the older-binary rejection mechanism (verified end to end), column-for-column schema alignment, the inspection-only Tinybird caveat and incompatible sorting-key change, Axum header-only semantics, DeliveryResult collected-but-unemitted, and the buffered-path request_elapsed_ms placement.
One nuance: "infallible by construction ... no panics" is accurate on locking and arithmetic, but slightly overstated given the unchecked phases[index] array access (noted inline, non-blocking).
| .as_ref() | ||
| .and_then(|_| diagnostics_auction_id(settings)); | ||
| let placeholder = mediator_placeholder_request(); | ||
| let wait_started = Instant::now(); |
There was a problem hiding this comment.
HIGH — Same wasm32-unknown-unknown panic, second site. CI structurally cannot catch this one.
publisher.rs:25 imports Instant from std::time, and this PR adds two new Instant::now() calls on the auction path (here in collect_non_html_auction, and again at :4002 in collect_stream_auction). Same target, same trap as the request_timing.rs finding.
The important part: the integration fixture sets [auction] enabled = false (crates/trusted-server-integration-tests/fixtures/configs/trusted-server.integration.toml:101), so my Cloudflare repro did not exercise these, and CI will still be green on these two lines even after the request_timing.rs fix lands. Cloudflare does dispatch auctions in production (adapter-cloudflare/src/app.rs:421-427).
Fixed as a local qualification rather than by changing the module-level import, since publisher.rs has pre-existing Instant call sites (template cache, lines 2224/4651) that this PR should not touch.
| let wait_started = Instant::now(); | |
| let wait_started = web_time::Instant::now(); |
Related, pre-existing and out of scope for this PR, but the same class and worth a follow-up issue: crates/trusted-server-core/src/auction/telemetry.rs:7 and crates/trusted-server-core/src/integrations/datadome/protection_scope.rs:5 also use std::time::Instant in Cloudflare-reachable core code.
There was a problem hiding this comment.
Fixed in 600746f as a local web_time::Instant::now() qualification at both auction-wait sites, leaving the module's std import for the pre-existing template-cache sites untouched. On the two pre-existing sites you flagged (auction/telemetry.rs, datadome/protection_scope.rs): agreed they are the same class and out of scope here; filed as a follow-up issue: #1075.
| log::info!("body_close_hold_loop: collecting dispatched auction before held body tail"); | ||
| let placeholder = mediator_placeholder_request(); | ||
| let collect_ctx = make_collect_context(settings, services, &placeholder); | ||
| let wait_started = Instant::now(); |
There was a problem hiding this comment.
HIGH — Second occurrence of the std::time::Instant trap on Cloudflare (see the note at :3940). This one is in collect_stream_auction.
| let wait_started = Instant::now(); | |
| let wait_started = web_time::Instant::now(); |
There was a problem hiding this comment.
Fixed in 600746f (same commit as the collect_non_html_auction site).
| /// sentinel rather than leave a dimension empty). `event_date` is omitted: | ||
| /// the datasource derives it from `event_ts` by default. |
There was a problem hiding this comment.
Stale doc. The final commit removed the event_date column entirely and switched to an expression sorting key (toDate(event_ts), …). There is no such column for the datasource to derive any more.
| /// sentinel rather than leave a dimension empty). `event_date` is omitted: | |
| /// the datasource derives it from `event_ts` by default. | |
| /// sentinel rather than leave a dimension empty). There is no `event_date` | |
| /// column: the datasource's sorting key derives the date via | |
| /// `toDate(event_ts)`. |
There was a problem hiding this comment.
Fixed in 3d7e697 with your suggested wording.
| // `into_parts()` consumes `response`: nothing else survives to | ||
| // post-send on every path (the request was consumed by dispatch, and | ||
| // `EcFinalizeState` is absent on asset, admin, and error paths). | ||
| let snapshot = build_access_telemetry_snapshot(&response, context); |
There was a problem hiding this comment.
Non-blocking — the access snapshot is built unconditionally, on the pre-send path.
build_access_telemetry_snapshot runs before into_parts() / send_to_client() for every response, including when tinybird.access_enabled is false — which is the default, and will be the steady state for most operators. It costs 3 × std::env::var plus roughly 6 String allocations per request, all of it upstream of first byte.
SendContext already exists and already carries server_timing_enabled, so threading the access flag through the same struct and gating this call is cheap. Given the TTFB findings in #1009, spending pre-send work on a disabled feature seems worth avoiding.
Worth confirming the snapshot is genuinely unused when the flag is off — if a downstream consumer reads it regardless, this is a non-issue and can be dismissed.
There was a problem hiding this comment.
Confirmed the snapshot is unused when the flag is off: the only consumer is emit_access_telemetry_after_send, which is gated on the same settings. Fixed in 38043d7: access_telemetry_enabled threads through SendContext, the snapshot build is skipped when off, and DeliveryOutcome.snapshot is now Option so the emitter treats a missing snapshot as nothing to send. The default configuration pays no env reads or allocations pre-send.
| /// Number of [`Phase`] variants; sizes the fixed-slot duration array in | ||
| /// [`Inner`]. | ||
| const PHASE_COUNT: usize = 8; |
There was a problem hiding this comment.
Non-blocking — PHASE_COUNT is hand-synced with Phase::index(), and the array access is unchecked.
inner.phases[index] indexes a fixed-size array using the value returned by Phase::index() (:52-63). Nothing ties the two together: adding a ninth Phase variant that returns index 8 compiles cleanly and panics at runtime on first use.
That is a small hole, but it sits directly under this module's own claim at :3-4 that collection is "infallible ... no panics" — which is otherwise accurate and well-earned (verified: all 7 lock sites are try_lock, and the arithmetic is saturating throughout).
Cheapest fix that preserves the claim is a test rather than a refactor:
#[test]
fn every_phase_index_is_unique_and_in_bounds() {
let phases = [
Phase::AppBuild,
Phase::Filter,
Phase::Geo,
Phase::EcKv,
Phase::Origin,
Phase::TemplateCacheLookup,
Phase::AuctionWait,
Phase::Stream,
];
let mut seen = [false; PHASE_COUNT];
for phase in phases {
let index = phase.index();
assert!(index < PHASE_COUNT, "should be in bounds: {phase:?} -> {index}");
assert!(!seen[index], "should be unique: {phase:?} -> {index}");
seen[index] = true;
}
assert!(seen.iter().all(|s| *s), "should cover every slot");
}A new variant then fails the test instead of the runtime. (Adding a variant without adding it to that array still slips through, but the match in index() makes that a compile error anyway.)
There was a problem hiding this comment.
Added in 38043d7, adapted from your sketch with the repo's assertion-message conventions.
| //! random values, flips the flags a local smoke test needs, validates the | ||
| //! result through [`trusted_server_core::settings::Settings::from_toml`], and | ||
| //! prints the blob envelope JSON that | ||
| //! `TRUSTED_SERVER_CONFIG_TRUSTED_SERVER_CONFIG_TRUSTED_SERVER_CONFIG` expects. |
There was a problem hiding this comment.
Botched find/replace — the env var name is tripled.
The Axum platform layer reads TRUSTED_SERVER_CONFIG_{STORE}_{KEY} (uppercased, hyphens → underscores) — see crates/trusted-server-adapter-axum/src/platform.rs:30,50.
| //! `TRUSTED_SERVER_CONFIG_TRUSTED_SERVER_CONFIG_TRUSTED_SERVER_CONFIG` expects. | |
| //! `TRUSTED_SERVER_CONFIG_{STORE}_{KEY}` expects. |
There was a problem hiding this comment.
Not a find/replace error, but it earned the double take: the Axum layer reads TRUSTED_SERVER_CONFIG_{STORE}_{KEY}, and with the default store and key both named trusted_server_config the concrete variable genuinely resolves to the tripled form. Reworded in 38043d7 to show the pattern first and label the resolved name explicitly.
std::time::Instant::now() panics on wasm32-unknown-unknown, so every publisher request on the Cloudflare adapter trapped when the timing collector was constructed, and the two auction-wait sites would trap once an auction dispatched. web_time re-exports std's Instant on every other target, so Fastly, Axum, and Spin behavior is unchanged. The publisher.rs sites are qualified locally because that module's std Instant import still serves the pre-existing template-cache sites, which are out of scope here.
The character allowlist alone does not bound identity: [a-z0-9_-] is exactly the alphabet UUIDs, hex ids, reset tokens, and article slugs are built from, and truncating to 32 characters still leaves a globally unique prefix. A first segment now rejects whole to /other/* when it exceeds 32 characters or carries more than 7 ASCII digits, alongside the existing charset rejection. Year archives and hyphenated section names still pass. Extends the adversarial tests to the publisher-fallback path with UUID, hex-id, token, and slug shapes, and fixes the stale event_date reference in the row-builder doc.
- Gate building the access snapshot on tinybird.enabled and access_enabled, threaded through SendContext: a disabled deployment (the default) no longer pays env reads and String allocations on the pre-send path. DeliveryOutcome.snapshot becomes Option and the emitter treats None as nothing to send. - Classify asset-fallback responses as route_class asset with the operator-configured route prefix as the template, instead of landing in the other/unknown bucket alongside 404s. - Pin Phase::index() to PHASE_COUNT with a uniqueness-and-bounds test so a future variant fails the suite instead of panicking at runtime. - Drop the tautological sampled-out emission test; the 0.0-rate behavior is covered by sampled_in_boundary_rates_are_unconditional. - Clarify that the local dev config env var name genuinely triples trusted_server_config (prefix, store, key) rather than reading as a find/replace mistake.
2 participants
Closes #1068. Implements the design in #1069 (
docs/superpowers/specs/2026-08-24-request-phase-timing-design.md); the implementation plan and the spec ride in the branch.What this adds
RequestTimings(core): always-on per-request phase collection;try_lock-only, saturating, infallible by construction.Server-Timingheader (ts-total,ts-appbuild,ts-filter,ts-geo,ts-kv,ts-origin,ts-template-cache) emitted at the send freeze point immediately beforeinto_parts(), gated byobservability.server_timing_enabledand restricted to conclusively private (private/no-store) responses so no shared cache can replay timings.TimedKvStoredecorator implementing bothPlatformKvStoreandEcKvStore(latency-only; reads no payloads). Pull-sync stores are explicitly untimed.GeoLookupStateresponse extension (NotAttempted/Attempted/Resolved), 401 rule preserved.DeliveryResult::{Complete, Partial, Error}), auction-wait with explicit placement (in_streamat the seam,pre_headeron buffered paths), response bytes, and a post-bodyrequest_elapsed_msthat excludes pull-sync and telemetry.AccessTelemetrySnapshotbuilt unconditionally at the freeze point, coarse PII-safe route templates (allowlist-reject; adversarially tested with EC ids, emails, search terms), and a confirmed-delivery Tinybird sink (bounded await, 2xx-validated, sampled bytinybird.access_sample_rate) that runs after client delivery and after pull-sync.access_logs_rawschema aligned column-for-column with the row producer; sorting key(toDate(event_ts), service_id, publisher_domain, env, route_class, pop, status); there is noevent_datecolumn (Tinybird's Events API requires a JSONPath on every column, which a derived-default column cannot carry).docs/guide/configuration.md.Review process
Eleven plan tasks, each implemented and passed an independent task-scoped review; two task-level fix rounds (settings validation coverage; a schema/producer nullability mismatch caught before it could quarantine rows at ingestion); a final whole-branch review on the full 13-commit diff followed by one fix wave (method-token normalization, a zero-sample-rate guard, geo write-back symmetry) and a clean scoped re-review.
Known limitations and rollout preconditions (disclosures)
access_logs_rawwas ever deployed remotely: the sorting key changed incompatibly from the reserved schema, so a deployed datasource means a versioned replacement with cutover, not an in-place edit. Panel queries needEXPLAINvalidation against the new key.[observability]table.ts-appbuild); Cloudflare and Spin collect but do not emit in v1. An earlier revision of this branch usedstd::time::Instant, which panics onwasm32-unknown-unknownand trapped every Cloudflare publisher request (the failingintegration testsruns on this branch); the timing paths now useweb_time::Instant, verified against the real workerd runtime locally.DeliveryResultis collected but not yet emitted on any surface (intentional groundwork).Partialsemantics are error-based only, per an explicit owner ruling: clean-but-early source truncation is out of scope permanently.request_elapsed_msis stamped beforesend_to_client(no drive to time); streaming responses, the case that matters for stall diagnosis, include the full drive.access_sample_rate = 1.0is a diagnosis setting, not a steady state.Generated with Claude Code