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.
ChristianPavilonis
left a comment
ChristianPavilonis
left a comment
There was a problem hiding this comment.
Summary
👍 Reviewed the exact head revision 38043d7464362d44519153a09fe850bacc256b58. The overall implementation direction is solid and all reported CI checks pass. I left seven actionable inline findings: three P2 telemetry-correctness issues and four P3 design/test-cleanup issues. There are no P0 or P1 findings.
| if rate <= 0.0 { | ||
| return false; | ||
| } | ||
| let threshold = (rate * ACCESS_SAMPLE_BUCKETS as f64) as u64; |
There was a problem hiding this comment.
🔧 P2 — Make the sampler's actual probability match access_sample_rate
Truncating rate * 1_000_000 means rates below 0.000001 produce a zero threshold and never emit. Other low rates are quantized downward; for example, 0.0000019 is sampled at 0.0000010 while emitted rows still carry sample_rate = 0.0000019. That makes valid positive configurations silently emit nothing and biases weighted queries such as sum(1.0 / sample_rate).
The timestamp-bits XOR response-size entropy also does not satisfy the design's uniform per-request decision. The core crate already uses rand::thread_rng() on Fastly and documents WASI randomness support, so please use a higher-resolution sampler backed by real randomness and add coverage for very small positive rates.
| platform_request = platform_request.with_cache_bypass(); | ||
| } | ||
|
|
||
| let origin_span = timings.span(Phase::Origin); |
There was a problem hiding this comment.
🔧 P2 — Stop the origin span before awaiting abandonment telemetry
When the origin request fails after an auction was dispatched, this guard remains active while emit_abandoned_auction(...).await runs. It is dropped only after the error branch, so ts-origin and Tinybird origin_ms can include Tinybird auction-telemetry work during an origin failure.
Please save the result of send(...).await, drop the origin span immediately, and then handle the success or error branch. An error-path test with a dispatched auction would cover the distinction that the current success-only origin-span test misses.
| NDJSON into a datasource without JSONPaths, discovered live); `event_date` was | ||
| dropped in favor of the sorting-key expression because a DEFAULT column cannot | ||
| carry a JSONPath the producer never sends. Grafana time filtering uses `$__timeFilter(event_ts)` and every panel query | ||
| also carries an `event_date` predicate so the primary index prunes; rollout validates |
There was a problem hiding this comment.
🔧 P2 — Remove event_date from dashboard and rollout guidance
The datasource has no event_date column; its sorting key uses toDate(event_ts). A dashboard query following this instruction will therefore fail with an unknown-column error. The same stale field also remains at line 412 and in the implementation plan at lines 931 and 934.
| also carries an `event_date` predicate so the primary index prunes; rollout validates | |
| also carries a `toDate(event_ts)` predicate so the primary index prunes; rollout validates |
| }; | ||
|
|
||
| build_router(&state) | ||
| Self::routes_with_server_timing_flag().0 |
There was a problem hiding this comment.
♻️ P3 — Do not discard timing configuration in the standard Axum application path
TimingService is not part of the returned RouterService, so callers using the existing Hooks::routes() or Hooks::build_app() interface get a different application from the shipped binary and silently ignore server_timing_enabled. The tuple is also an opaque public construction API whose Boolean is meaningful only to the custom runner.
The outer service is justified here chiefly by router-generated 404/405 responses, but those responses also bypass finalization and are not conclusively private; the 404 test has to manufacture a private response. Please consider using an outermost EdgeZero timing middleware. If the Tower wrapper is genuinely required, expose a named, fully configured application/service and make that the standard construction path rather than returning (RouterService, bool).
| /// Response body size in bytes. | ||
| pub bytes: u64, | ||
| /// Whether delivery completed or failed partway. | ||
| pub result: DeliveryResult, |
There was a problem hiding this comment.
♻️ P3 — Remove or consume the unused delivery classification
DeliveryOutcome.result is classified as complete, partial, or error but is never read in production; #[allow(dead_code)] hides that fact. The datasource also has no delivery-result field. This leaves classification code and tests that affect neither telemetry, logging, nor behavior.
Since buffered delivery cannot reliably detect partial delivery and the schema does not consume the value, please remove DeliveryResult, its classifier, and its tests. If the value is operationally required, wire it into the access row and datasource instead of suppressing the warning.
| // function for entry-point finalize headers. | ||
| match settings_snapshot.as_deref() { | ||
| Some(settings) => emit_access_telemetry_after_send(settings, &outcome, &timings), | ||
| None => match load_settings_from_config_store() { |
There was a problem hiding this comment.
♻️ P3 — Remove the fallback reload that cannot emit telemetry
When settings_snapshot is absent, access_telemetry_enabled is necessarily false, so send_edgezero_response produces snapshot: None. Reloading settings here can never emit a row because the emitter exits on the missing snapshot. For the same reason, the documented production path where a snapshot carries sample_rate: 0.0 cannot occur.
Please skip access emission directly when the initial settings snapshot is absent. The separate snapshot-rate guard and tests that manually construct the unreachable zero-rate snapshot can then be removed as well.
| } | ||
|
|
||
| #[test] | ||
| fn post_send_order_is_elapsed_then_pull_sync_then_telemetry() { |
There was a problem hiding this comment.
🔧 P3 — This test does not cover production post-send ordering
The test manually appends pull_sync to a vector and then manually calls the telemetry emitter. It will continue passing if the real calls in edgezero_main are reordered; the comment below acknowledges that production ordering is still verified only through source inspection.
Either extract the post-send orchestration behind injectable pull-sync and telemetry seams and test that function, or narrow this test to the behavior it actually proves: request elapsed time has been stamped when sending returns.
ChristianPavilonis
left a comment
ChristianPavilonis
left a comment
There was a problem hiding this comment.
Summary
🔧 Superseding my prior approval for 38043d7464362d44519153a09fe850bacc256b58: please address the seven inline findings already posted in the preceding review, particularly the three P2 telemetry-correctness issues, before merge. The existing inline threads remain the actionable review details and are not duplicated here.
prk-Jr
left a comment
prk-Jr
left a comment
There was a problem hiding this comment.
Summary
Substantial, carefully-built observability layer: 27 files, ~6.5k insertions, with a
freeze-point design that reads typed response extensions rather than the headers they
back, symmetric geo write-back on both finalize sites, and adversarial route-template
tests. All 19 GitHub checks pass and I reproduced every CI gate locally (2450 Fastly +
40 Axum + 39 Cloudflare + 79 Spin + 13 parity Rust tests, 871 JS tests).
One blocking finding, and it is a spec-conformance question rather than a crash risk:
publisher_route_template does not meet section 9 of
docs/superpowers/specs/2026-08-24-request-phase-timing-design.md for single-segment
paths. Everything else below is non-blocking.
I also checked the access sampler for modulo bias and it came back clean — see the
note in the cross-cutting section, since it is the kind of thing worth recording as
verified rather than leaving as an open question.
4 of the inline comments below carry a one-click GitHub
suggestion. I applied all
four together in a scratch worktree at this head and verified them:
cargo fmt --all -- --checkPASS,cargo clippy-fastlyPASS (0 warnings),
trusted-server-corelib 2238 passed / 0 failed,trusted-server-adapter-fastly
185 passed / 0 failed.
Blocking
🔧 wrench
publisher_route_templatekeeps single-segment article slugs verbatim, against spec section 9 — inline atcrates/trusted-server-core/src/access_telemetry.rs:189
Non-blocking
🤔 thinking
Server-Timingis an unrestricted client-visible latency oracle when enabled — inline atcrates/trusted-server-core/src/request_timing.rs:285
♻️ refactor
HEADER_PHASESis a second hand-synced list with no test — inline atcrates/trusted-server-core/src/request_timing.rs:419#[allow(dead_code)]on the wholeDeliveryOutcomemasks two live fields — inline atcrates/trusted-server-adapter-fastly/src/main.rs:571
🏕 camp site
route_class_renders_snake_caseomits the newAssetvariant — inline atcrates/trusted-server-core/src/access_telemetry.rs:526
⛏ nitpick
- Test name asserts the opposite of what it tests — inline at
crates/trusted-server-core/src/access_telemetry.rs:439
👍 praise
- Freeze point reads extensions, not headers — inline at
crates/trusted-server-adapter-fastly/src/main.rs:797
Cross-cutting
-
✅ Checked and clean: the access sampler is not modulo-biased.
entropy = since_epoch.as_nanos() as u64 ^ outcome.bytesthenentropy % 1_000_000 < rate * 1e6looks like it could starve whole response-size classes, because the guest wall clock is microsecond-resolution andnanosis therefore always a multiple of 1000. It does not:as_nanos()since epoch is a ~61-bit monotonically advancing value, and% 1_000_000folds the high bits back in, so residues walk the whole bucket range across requests. Measured at n=200,000 per size against the binomial 3σ band, with the clock spread over a realistic arrival window: fixed sizes of 200 B, 4 KB, 64 KB, 100 KB, ~1 MB and 1.5 MB all land inside the band at bothaccess_sample_rate = 0.05and0.01; 0/400 random sizes are ever starved. Freezing the clock inside a single millisecond does produce an apparent bias, but that is an artifact of collapsing the reachable residue set, not a property of the sampler. No change wanted here —sampled_in's "approximately even, not provably unbiased" doc comment is accurate as written. -
📌
std::time::Instant::now()still traps onwasm32-unknown-unknownin ~15 pre-existing core sites. This PR correctly moved its own timing paths toweb_time, and #1075 tracks two of the neighbours — but the set is wider than that issue records:crates/trusted-server-core/src/auction/orchestrator.rs(lines 101, 295, 332, 375, 509, 581, 978, 1045, 1348),crates/trusted-server-core/src/auction/telemetry.rs:178,202,crates/trusted-server-core/src/integrations/datadome/protection_scope.rs:405,435, andcrates/trusted-server-core/src/publisher.rs:2259,4734(the template-cache TTL sites the new comments explicitly point at). Out of scope to change here; worth widening #1075's scope so the Cloudflare auction, DataDome-scope and template-cache-TTL paths are not left believed-covered. -
📝 The Axum adapter now hand-rolls
AxumDevServer's serve loop.crates/trusted-server-adapter-axum/src/main.rsreplacesAxumDevServer::with_config(router, config).run()with a localrun/servepair. Diffed against the pinned rev (edgezerotagv0.0.4,9e661ae,crates/edgezero-adapter-axum/src/dev_server.rs:274-321) and it is faithful:AxumDevServerConfighas exactlyaddrandenable_ctrl_cand both are honoured,serve_with_storeswithStores::default()inserts nothing extra, and theRouter::new().fallback_service(service_fn(...))+into_make_service_with_connect_info::<SocketAddr>()shape matches line for line. Only deviation istokio::net::TcpListener::bindwhere upstream binds astdlistener and callsfrom_std— behaviourally equivalent here. No finding against the code as written; the note is drift risk, since this copy will silently diverge at the nextedgezerorepin. Upstreaming a service-layer hook (AxumDevServer::with_service_layer) would let the fork go away. -
📝 Phase spans are not disjoint, so header subtimings do not partition
ts-total.Phase::Streamdeliberately encloses the in-stream auction wait —stream_drive_records_stream_ms_covering_the_in_stream_auction_waitassertsstream_ms >= auction_wait_ms— and every span is RAII across.await, so it measures wall clock including suspension rather than work. Both are the right choices for stall diagnosis, butdocs/guide/configuration.md's new "Observability" section reads as if the entries were a breakdown. One sentence saying the entries may overlap and do not sum tots-totalwould stop an operator drawing the wrong conclusion from the header. -
📝
ObservabilitySettings' rollback doc attributes the protection to the wrong attribute.crates/trusted-server-core/src/settings.rssays ofObservabilitySettings: "this struct denies unknown fields, so an older binary loading a config blob carrying an[observability]table it does not know would reject it, breaking rollback." The mechanism that actually makes rollback unsafe is#[serde(deny_unknown_fields)]onSettingsitself (settings.rs:2653) in the older binary;ObservabilitySettings' own attribute only rejects unknown keys inside the table in the new binary. The conclusion and theskip_serializing_if = "ObservabilitySettings::is_default"guard are both correct — only the stated reason is off, and it would mislead the next reader who tries to relax either attribute.
Verification performed
Scratch worktree at PR head 38043d74:
| Gate | Result |
|---|---|
gh pr checks 1074 |
19/19 PASS, 0 failing, 0 pending |
cargo fmt --all -- --check |
PASS |
cargo clippy-fastly / -axum / -cloudflare / -cloudflare-wasm / -spin-native / -spin-wasm |
PASS (all six) |
cargo test-fastly |
PASS — 2450 passed, 0 failed, 10 ignored |
cargo test-axum |
PASS — 40 passed, 0 failed |
cargo test-cloudflare |
PASS — 39 passed, 0 failed |
cargo test-spin |
PASS — 79 passed, 0 failed |
| parity suite | PASS — 13 passed, 0 failed |
npx vitest run |
PASS — 45 files, 871 tests, 0 failed |
Could not verify
- Fastly Compute production wall-clock granularity — the microsecond resolution behind the sampler check was measured under Viceroy on
wasm32-wasip1, not on Fastly Compute. The clean result holds for any granularity finer than a millisecond, so this does not change the conclusion. - Cloudflare
web_time::Instantbehaviour on workerd — no workerd here; taking the description's word that it was verified. Worth noting Workers deliberately freezes clocks between I/O, so CPU-only phases will likely read0there. Harmless while Cloudflare does not emit, but the collected values are not usable as-is if emission is turned on later. - Tinybird schema deployment state —
ENGINE_SORTING_KEYchanged incompatibly from the reserved schema; whetheraccess_logs_rawwas ever deployed remotely (and so whether this needs a versioned replacement plus cutover rather than an in-place edit) is a live-account question. Already disclosed as a rollout precondition; notbCLI here. - Fronting delivery layer
Server-Timingpass-through — needs a staging deploy; already disclosed. emit_access_eventagainst real Tinybird — exercised only through the recording double, so the live ingest contract is unverified.
| let within_length = lowered.chars().count() <= MAX_SEGMENT_LEN; | ||
| let digit_count = lowered.chars().filter(char::is_ascii_digit).count(); | ||
|
|
||
| if !is_allowlisted || !within_length || digit_count > MAX_SEGMENT_DIGITS { |
There was a problem hiding this comment.
🔧 wrench — Single-segment publisher paths land in the 30-day dataset verbatim, which the spec says they must not.
Spec section 9 lists the required rejections: "segments, UUIDs, hex ids, reset tokens, and full article slugs must all normalize to bounded, content-free templates" (docs/superpowers/specs/2026-08-24-request-phase-timing-design.md:300-301). The length and digit bounds catch the long cases, but a single-segment path shorter than MAX_SEGMENT_LEN with at most MAX_SEGMENT_DIGITS digits is returned as-is:
/hiv-diagnosis -> /hiv-diagnosis
/bankruptcy-help -> /bankruptcy-help
/abortion -> /abortion
/my-post-title/ -> /my-post-title
/1234567 -> /1234567
/user-8f3a9c2b -> /user-8f3a9c2b
The last three matter as much as the first three: a 7-digit numeric post id sits exactly at the MAX_SEGMENT_DIGITS boundary and is a very common CMS permalink, and /user-8f3a9c2b is a short opaque id that passes both bounds.
/my-post-title/ is the one I would weigh heaviest. That is the WordPress /%postname%/ permalink structure — WordPress's own recommended default — under which every article URL is a single-segment path. For a publisher on that config, route_template stops being a route identity and becomes the full request path, in a 30-day dataset. The neighbouring test asserting /how-to-treat-my-recent-hiv-diagnosis normalizes to /other/* reads as protection against exactly this, but it passes only because that particular string happens to be 36 characters.
The function's own doc comment already concedes the gap ("Short all-alpha slugs on single-segment paths are indistinguishable from section names and still pass; the bound here is shape-based, not semantic"), so the code is honest — but spec section 9 and the PR description ("coarse PII-safe route templates … adversarially tested") still advertise the stronger guarantee. Three artefacts disagree and one of them has to move.
Two ways to reconcile, your call:
(a) Tighten. The whole design rests on the first segment being a section; on a single-segment path the first segment is the document. Bucketing those into the existing /other/* needs no new constant and no config surface:
if !is_allowlisted || !within_length || digit_count > MAX_SEGMENT_DIGITS {
return "/other/*".to_owned();
}
if has_more_depth {
format!("/{lowered}/*")
} else {
// A single-segment path's first segment is the document, not a
// section: `/my-post-title` under WordPress `/%postname%/` is a
// per-article slug. Only depth >= 2 makes the first segment a
// section name.
"/other/*".to_owned()
}That costs real signal — /about, /contact and every root-level landing page collapse into /other/* — so it may not be the trade you want. Keeping single-segment templates behind an operator-supplied allowlist of known section names would preserve it, but that needs config surface and belongs in a follow-up issue rather than this PR.
(b) Amend the claim. Keep the code and correct spec section 9's rejection list plus the PR description so neither promises that article slugs normalize away, saying plainly that single-segment paths up to MAX_SEGMENT_LEN reach the dataset verbatim.
Not offered as a one-click suggestion because (a) pairs with a spec edit and a PR-description change, and (b) is entirely outside the diff.
One thing I checked that is not a problem: route_template is a plain String in tinybird/datasources/access_logs_raw.datasource, not LowCardinality, and it is absent from ENGINE_SORTING_KEY, so unbounded distinct values cost storage but do not degrade the index. This is purely about what content reaches the dataset.
| /// Generic over the response body type so every adapter's terminal layer can | ||
| /// call the same emission logic regardless of which body type its HTTP stack | ||
| /// uses. | ||
| pub fn append_server_timing_if_private<B>( |
There was a problem hiding this comment.
🤔 thinking — Enabling server_timing_enabled hands every client a per-phase server latency oracle, and the docs do not say so.
The emission gate is "conclusively private response" plus the config flag — there is no restriction on who receives the header. So any caller of /_ts/api/v1/identify (public, and it reads the EC identity graph through TimedKvStore) gets ts-kv back as a measured duration, and ts-origin / ts-template-cache expose origin and cache-store behaviour on publisher pages.
That is standard Server-Timing practice and the flag is correctly off by default, so this is not a defect. The concern is framing: docs/guide/configuration.md's new section presents it as a general operator toggle rather than a debug aid, so an operator could reasonably leave it on in production without realising they have published KV read latency on an identity endpoint.
Cheapest resolution is documentation — one paragraph in the new "Observability" section stating that the header is client-visible and what it discloses. If you would rather restrict it, the repo already has a per-request opt-in surface in [tester_cookie] / ts-tester that emission could gate on, but that is a design change, so a doc note plus a follow-up issue seems right for this PR.
Apply manually — the change lands in docs/guide/configuration.md, outside this file's hunks.
| assert!( | ||
| seen.iter().all(|slot| *slot), | ||
| "should cover every phases-array slot" | ||
| ); |
There was a problem hiding this comment.
♻️ refactor — HEADER_PHASES is a second hand-synced list, and this new test does not cover it.
every_phase_index_is_unique_and_in_bounds closes the PHASE_COUNT / Phase::index() trap nicely. But HEADER_PHASES (:312-319) and Phase::header_name() (:70) are hand-synced in exactly the same way, with a quieter failure mode: a new phase that gains a header_name() but is never added to HEADER_PHASES compiles, tests green, and simply never renders in the Server-Timing value.
The corollary is already visible — the let Some(name) = phase.header_name() else { continue }; inside server_timing_value's loop (:228-230) is unreachable, because HEADER_PHASES only ever holds header-bearing phases. That continue arm is dead precisely as long as the two lists agree, which is the thing nothing checks.
Extending the test you just added covers it in the same place, and also pins the declaration order the doc comment promises:
| ); | |
| ); | |
| // `HEADER_PHASES` is a second hand-synced list: a phase that gains a | |
| // `header_name()` but is never added here silently renders nothing. | |
| let header_bearing: Vec<Phase> = phases | |
| .into_iter() | |
| .filter(|phase| phase.header_name().is_some()) | |
| .collect(); | |
| assert_eq!( | |
| header_bearing, HEADER_PHASES, | |
| "should render every header-bearing phase, in declaration order" | |
| ); |
Verified in a scratch worktree at this head: cargo fmt --all -- --check PASS, cargo clippy-fastly PASS (0 warnings), trusted-server-core lib 2238 passed / 0 failed.
| #[allow(dead_code)] | ||
| pub(crate) struct DeliveryOutcome { | ||
| /// Response body size in bytes. | ||
| pub bytes: u64, | ||
| /// Whether delivery completed or failed partway. | ||
| pub result: DeliveryResult, | ||
| /// Access-telemetry dimensions captured for this response at the | ||
| /// freeze point. `None` when access telemetry was disabled at snapshot | ||
| /// time; the emitter treats that as nothing to send. | ||
| pub snapshot: Option<AccessTelemetrySnapshot>, | ||
| } |
There was a problem hiding this comment.
♻️ refactor — the struct-level #[allow(dead_code)] also silences two fields that are live.
Only result is unread in production — that is the intentional groundwork the description discloses. bytes and snapshot are both read by emit_access_telemetry_after_send (bytes for the sampling entropy, snapshot for the row), so a struct-level allow buys nothing for them and costs the compiler's coverage if either later stops being used. Narrowing it to the one field that needs it keeps the disclosure precise and self-documenting:
| #[allow(dead_code)] | |
| pub(crate) struct DeliveryOutcome { | |
| /// Response body size in bytes. | |
| pub bytes: u64, | |
| /// Whether delivery completed or failed partway. | |
| pub result: DeliveryResult, | |
| /// Access-telemetry dimensions captured for this response at the | |
| /// freeze point. `None` when access telemetry was disabled at snapshot | |
| /// time; the emitter treats that as nothing to send. | |
| pub snapshot: Option<AccessTelemetrySnapshot>, | |
| } | |
| pub(crate) struct DeliveryOutcome { | |
| /// Response body size in bytes. | |
| pub bytes: u64, | |
| /// Whether delivery completed or failed partway. Collected as | |
| /// groundwork; not yet emitted on any surface. | |
| #[allow(dead_code)] | |
| pub result: DeliveryResult, | |
| /// Access-telemetry dimensions captured for this response at the | |
| /// freeze point. `None` when access telemetry was disabled at snapshot | |
| /// time; the emitter treats that as nothing to send. | |
| pub snapshot: Option<AccessTelemetrySnapshot>, | |
| } |
Verified in a scratch worktree at this head: cargo fmt --all -- --check PASS, cargo clippy-fastly PASS with 0 warnings — which is the point, since it confirms bytes and snapshot really are read and the narrowed allow is sufficient. trusted-server-adapter-fastly 185 passed / 0 failed.
Related and much smaller: classify_stream_delivery's Ok(()) => Complete arm is unreachable from its only production call site, since the Ok branch there re-derives the outcome from streaming_body.finish() and the precomputed result is consumed only in the Err arm. It is exercised by classify_stream_delivery_treats_ok_as_complete, so it is not dead code — just worth a word in the function doc that the Ok arm exists for the classifier's totality rather than for the caller.
| assert_eq!(RouteClass::Tsjs.as_str(), "tsjs"); | ||
| assert_eq!(RouteClass::IntegrationProxy.as_str(), "integration_proxy"); | ||
| assert_eq!(RouteClass::Ec.as_str(), "ec"); | ||
| assert_eq!(RouteClass::AuctionApi.as_str(), "auction_api"); |
There was a problem hiding this comment.
🏕 camp site — RouteClass::Asset, the variant this PR's last fix wave added, is the one variant this test does not cover, so a typo in its as_str() would ship silently into the route_class column.
| assert_eq!(RouteClass::AuctionApi.as_str(), "auction_api"); | |
| assert_eq!(RouteClass::AuctionApi.as_str(), "auction_api"); | |
| assert_eq!(RouteClass::Asset.as_str(), "asset"); |
Verified: cargo fmt --all -- --check PASS, cargo clippy-fastly PASS, trusted-server-core lib 2238 passed / 0 failed.
| fn publisher_route_template_uppercases_lowercase_before_allowlisting() { | ||
| assert_eq!( | ||
| publisher_route_template("/News/Article"), | ||
| "/news/*", | ||
| "should lowercase before validating and truncating" |
There was a problem hiding this comment.
⛏ nitpick — the name says the opposite of what the test does (it lowercases uppercase input, not the reverse), and the message still mentions truncation, which the reject-whole-segment rewrite removed.
| fn publisher_route_template_uppercases_lowercase_before_allowlisting() { | |
| assert_eq!( | |
| publisher_route_template("/News/Article"), | |
| "/news/*", | |
| "should lowercase before validating and truncating" | |
| fn publisher_route_template_lowercases_before_allowlisting() { | |
| assert_eq!( | |
| publisher_route_template("/News/Article"), | |
| "/news/*", | |
| "should lowercase before validating" |
Verified: cargo fmt --all -- --check PASS, cargo clippy-fastly PASS, trusted-server-core lib 2238 passed / 0 failed.
| context: &SendContext, | ||
| ) -> AccessTelemetrySnapshot { | ||
| let (route_class, route_template) = match response.extensions().get::<RouteMetadata>() { | ||
| Some(metadata) => (metadata.route_class, metadata.route_template.clone()), |
There was a problem hiding this comment.
👍 praise — building the snapshot from typed extensions rather than the headers those extensions back is the right call, and the reasoning in the doc comment is exactly right: an operator [response_headers] override can shadow x-ts-template-cache, and the row would then disagree with what actually happened. template_cache_response_extension_matches_the_header_on_every_transition pinning the two together on both the cold-fill and warm-hit transitions is what makes that safe to rely on.
Same for should_sample_access_row's degraded-rate guard — catching that a sample_rate: 0.0 snapshot from the app-state-build-failure path could otherwise be sampled in by reloaded settings and corrupt sum(1.0 / sample_rate) is a subtle one, and splitting it out so it is unit-testable without a network seam was the right shape.
3 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