From 9f01f5fdab8eb588ac52f1d854bf0a661261ac2f Mon Sep 17 00:00:00 2001 From: Jason Evans Date: Mon, 24 Aug 2026 12:01:09 -0500 Subject: [PATCH 1/5] Add request phase timing design spec (Server-Timing subtimings + access telemetry) --- .../2026-08-24-request-phase-timing-design.md | 287 ++++++++++++++++++ 1 file changed, 287 insertions(+) create mode 100644 docs/superpowers/specs/2026-08-24-request-phase-timing-design.md diff --git a/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md b/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md new file mode 100644 index 000000000..b7f9d7d2f --- /dev/null +++ b/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md @@ -0,0 +1,287 @@ +# Request phase timing: Server-Timing subtimings and access telemetry + +**Date:** 2026-08-24 +**Status:** Approved design, pending implementation plan. +**Scope:** `trusted-server-core`, Fastly and Axum adapters, `tinybird/` schema and pipes, +performance dashboard (separate repo). + +--- + +## 1. Problem + +On 2026-08-21 a production deployment (publisher redacted, `prospect-a.com`) showed an +episodic stall: for a window of roughly 40 minutes, every request that reached the +application path carried a uniform extra ~600 ms of Fastly `time-elapsed`, and then +recovered to 20-50 ms with no deploy or config change we could observe. `/health` +(2-4 ms, short-circuits before app construction) and `/_ts/debug/ja4` (6-9 ms, settings +load only) stayed fast throughout, so the stall lived between app construction and +response send. + +Attributing that window required a live probing session: route-by-route bisection, +cookie-deletion experiments, and an eight-agent code trace. The trace found no +unconditional await on the path that could cost 570 ms, and exactly two +config-conditional candidates (the pre-route request filter's synchronous verification +POST, and EC identity KV writes before send), plus one dependency shared by every +application route (two geo hostcalls per request). We could not tell which one stalled, +because nothing in the response says where server time went. + +The Compute CPU budget is ~50 ms per request, so any large `time-elapsed` is wall-clock +await on a dependency by definition. Those are exactly the numbers a response can carry +about itself. + +## 2. Goals + +1. Every response attributes its own server time by phase, in a standard header that + browsers expose to JavaScript (`PerformanceResourceTiming.serverTiming`), so any RUM + tool the publisher already runs picks up the breakdown with zero integration work. +2. The same numbers flow to Tinybird so we hold p50/p95/p99 per phase, per route class, + per PoP, per deployed version, and a future stall window self-diagnoses in one query. +3. Zero cost to TTFB: collection is a handful of monotonic clock reads; telemetry + emission happens strictly after the last body byte. + +## 3. Non-goals + +- No trailer-based Server-Timing for body-phase spans (browsers do not expose trailer + values to JavaScript). +- No per-filter naming in any emitted surface. The request-filter span is `ts-filter` + regardless of which filter runs; vendor identity stays out of headers and telemetry. +- No Cloudflare or Spin emission wiring in v1. Core collection is adapter-neutral; those + adapters can wire emission later without core changes. +- No rollup materialized views. The raw datasource plus one endpoint pipe is v1; + rollups only if panel latency demands them. +- No sampling of the header. The header is all-traffic when enabled; only Tinybird rows + sample. + +## 4. Design overview + +``` +adapter entry (T0) + | RequestTimings::new() -> request extensions + v +app construction ................ ts-appbuild (adapter) +pre-route request filters ....... ts-filter (adapter wrapper) +geo lookup (single, deduped) .... ts-geo (adapter; result stashed) +EC KV before send ............... ts-kv (core: ec/finalize.rs) +template cache lookup ........... ts-c2 (core: publisher.rs) +origin fetch to resp headers .... ts-origin (core: publisher.rs) + | +finalize middleware: + append Server-Timing header ... ts-total + all recorded spans + | +headers committed; body streams + auction hold at seam .......... auction_wait_ms (row only) + stream duration, bytes ........ stream_ms, resp_bytes (row only) + | +post-send (adapter main): + sample gate -> one NDJSON row -> Tinybird Events API (best effort) +``` + +Collection is always-on and flag-free. Two independent flags gate emission: the header +(`observability.server_timing_enabled`) and the telemetry row (`tinybird.access_enabled`). + +## 5. `RequestTimings` (core) + +New module `crates/trusted-server-core/src/request_timing.rs`. + +- `Phase`: a closed enum: `AppBuild`, `Filter`, `Geo`, `EcKv`, `Origin`, `C2Lookup`, + `AuctionWait`, `Stream`. Header rendering covers the first six plus the derived + total; the last two are row-only. +- Inner state: one fixed-size array of `Option` slots indexed by phase, plus + `t0: Instant`, plus `resp_bytes: Option`. Phases that repeat within a request + (geo, KV) accumulate by saturating addition into the same slot. +- Sharing: `RequestTimings` is a cheap-clone handle, `Arc>`. It must cross + three boundaries: request extensions (adapter entry to core handlers), the streaming + body closure (records body-phase spans after the response object has been handed + off), and the adapter's post-send emission read. A poisoned or contended lock must + never fail a request: all recording methods are infallible and drop the sample on + lock failure. +- Recording API: `timings.record(Phase::Geo, dur)` and a scope guard + `timings.span(Phase::Origin)` that records on drop. Guards use saturating duration + math; a non-monotonic reading records zero rather than panicking. +- Rendering: `server_timing_value(&self) -> Option` produces + `ts-total;dur=41.2, ts-appbuild;dur=18.4, ts-filter;dur=9.1` with durations in + milliseconds at one decimal. Phases never recorded are omitted. `ts-total` is + elapsed-since-`t0` at render time, which by construction is the last mutation before + send. Returns `None` when nothing was recorded (defensive; `t0` always exists). + +`Instant` is already used freely in the guest (`publisher.rs`, `auction/telemetry.rs`), +so no new clock abstraction is needed. + +## 6. Span taxonomy and recording sites + +| Entry | Measures | Site | +| ------------- | ------------------------------------------------------------------------- | --------------------------------------------------------------------------------------- | +| `ts-total` | adapter entry (post health short-circuit) to header emission | derived at render | +| `ts-appbuild` | config-store open, Settings parse, orchestrator + registry + router build | Fastly `main.rs` around `open_trusted_server_config_store()` + `build_app_with_state()` | +| `ts-filter` | pre-route request filters, end to end (backend ensure, secret read, POST) | around `run_pre_route_filters` (`app.rs:751`) | +| `ts-geo` | geo hostcall (single after dedupe; accumulates if any path still repeats) | `build_ec_request_state` (`app.rs:410`) | +| `ts-kv` | EC identity KV operations before send | `ec/finalize.rs` ingest path, EC-route KV lookups | +| `ts-origin` | publisher backend send to response headers available (C1 hit or miss) | `publisher.rs` around the origin `send` (~line 4496) | +| `ts-c2` | template cache `lookup_or_reserve`, including the hit-path full-body read | `publisher.rs` around the lookup (~line 4391) | + +Row-only fields: + +| Field | Measures | Site | +| ----------------- | -------------------------------------------------------- | ------------------------------------------------- | +| `auction_wait_ms` | hold at the `` seam waiting on dispatched auction | `collect_stream_auction` / seam wait in publisher | +| `stream_ms` | headers committed to last body byte | adapter around the body-stream drive | +| `resp_bytes` | bytes written to the client body | same | + +## 7. Header emission + +The last step of `apply_finalize_headers` (`middleware.rs:197`) appends one +`Server-Timing` header from `server_timing_value()`, gated on +`observability.server_timing_enabled`. Append semantics, never insert: an +origin-supplied Server-Timing survives, and the fronting delivery layer's own entries +(`time-elapsed`, `hit-state`) are additive per the header's list semantics. + +Emission runs after the finalize geo resolution and after every configurable response +mutation, so the header reflects everything that happened before send. Both finalize +sites (the router middleware and the adapter entry-point fallback for streaming +responses) emit through the same helper; the `HEADER_X_TS_FINALIZED` marker already +prevents double-finalization, which also prevents a doubled header. + +## 8. Geo lookup dedupe (rider) + +Today every dispatched request pays two geo hostcalls for one answer: request-phase in +`build_ec_request_state` (`app.rs:410`) and response-phase in +`FinalizeResponseMiddleware` (`middleware.rs:83`, alternate site `main.rs:285`). The +first lookup stashes the resolved `GeoInfo` in request extensions; the finalize path +reads the stashed value and only falls back to a live lookup when the request-phase +never ran. This halves exposure to a degraded geo subsystem, which is one of the three +candidate dependencies for the observed stall window. The 401 short-circuit behavior +(`resolve_geo_for_response` skips lookup for unauthorized responses) is preserved. + +## 9. Access telemetry row + +Extends the reserved `tinybird/datasources/access_logs_raw.datasource` (in-repo only, +no deployed pipes over it, so this is an edit rather than a migration). + +Kept columns: `event_ts`, `method`, `path`, `status`, `time_elapsed_ms` (now defined as +`ts-total`), `cache_state`, `country`, `sample_rate`, `event_date`, 30-day TTL. + +Added columns: + +``` +`route_class` LowCardinality(String), -- publisher_html | tsjs | integration_proxy | ec | auction_api | other +`appbuild_ms` Nullable(UInt32), +`filter_ms` Nullable(UInt32), +`geo_ms` Nullable(UInt32), +`kv_ms` Nullable(UInt32), +`origin_ms` Nullable(UInt32), +`c2_ms` Nullable(UInt32), +`auction_wait_ms` Nullable(UInt32), +`stream_ms` Nullable(UInt32), +`resp_bytes` Nullable(UInt64), +`c2_state` LowCardinality(Nullable(String)), -- x-ts-c2-cache value +`ts_version` LowCardinality(String), +`pop` LowCardinality(Nullable(String)) -- FASTLY_POP +``` + +Null means the phase did not run. `route_class` is assigned by the adapter at handler +selection (the named-route table knows which handler it picked), not by path regex. +Percentile analysis groups by `route_class`; `path` stays for drill-down only. + +## 10. Emission mechanics + +- Point: Fastly `main.rs`, strictly after `send_edgezero_response` returns (the body + has fully streamed). The row can never affect TTFB or block delivery. +- Sampling: uniform per-request decision against `tinybird.access_sample_rate` + (validation `0.0..=1.0` already exists). No client stickiness. +- Transport: one NDJSON row to the Tinybird Events API, mirroring the auction sink + (`tinybird.rs`): same `api_host`, reserved `access_dataset` and + `access_token_secret`, 2 s first-byte and between-bytes timeouts, `max_body_bytes` + guard, best-effort with a warn log on failure, no retry. +- Settings: the guard that rejects `tinybird.access_enabled = true` "until an emitter + is wired" (`settings.rs:4123` test) flips into a wiring test in the same change, so + the flag and the emitter land together. `access_enabled = true` requires + `tinybird.enabled` and a non-empty `api_host`. +- Axum adapter: emits the header via the same core helper; does not emit Tinybird rows + in v1 (local dev has no Tinybird backend; the sink stays behind the Fastly adapter). + +## 11. Pipe and dashboard + +- `tinybird/pipes/access_phase_stats.pipe`: endpoint returning p50/p95/p99 of each + phase column grouped by `route_class` and hour, filterable by `pop` and `ts_version`. +- Dashboard: a new standalone `grafana/dashboards/edge-performance.json` in the + telemetry repo (`trusted-server-tinybird`), performance only, no panels shared with + the revenue and auction dashboards. Panels: phase percentiles by route class, stacked + phase breakdown over time, PoP split, version overlay, C2 hit-rate, and a stall + panel: rows with `time_elapsed_ms > 500` grouped by dominant phase. Queries hit the + raw datasource with `$__timeFilter(event_ts)`. + +## 12. Config surface + +```toml +[observability] +# Append TS phase timings to the Server-Timing response header. +server_timing_enabled = false # example default + +[tinybird] +access_enabled = false # requires tinybird.enabled and api_host when true +access_sample_rate = 0.0 # 1.0 during active diagnosis, dial down after +``` + +New `ObservabilitySettings` struct with the single boolean, default off, standard +environment override (`TRUSTED_SERVER__OBSERVABILITY__SERVER_TIMING_ENABLED`). +Collection has no flag: the flags gate the two emission surfaces independently. + +## 13. Error handling + +- Recording is infallible: saturating math, lock-failure drops the sample, no panics. +- Header rendering failure (invalid header value cannot occur with the fixed format; + defensive `HeaderValue::from_str` error) logs and skips the header. +- Row emission failure logs a warning and drops the row. The response has already been + delivered; there is nothing to degrade. + +## 14. Testing + +- Core unit tests: phase accumulation, saturating math, render format (one decimal, + omission of unrecorded phases, `ts-total` presence), row serialization shape. +- Adapter tests (Fastly via Viceroy, Axum native): header present and well-formed on a + publisher route and on the tsjs route with the flag on; absent with the flag off; + exactly one header after both finalize paths; append preserves a pre-existing + Server-Timing value. +- Geo dedupe: finalize consumes the stashed request-phase `GeoInfo`; live-lookup + fallback fires when the request phase never ran; 401 skip preserved. +- Settings: `access_enabled` validation matrix (requires `tinybird.enabled`, + `api_host`); the former rejection test becomes the wiring test. +- Sink tests: mirror the auction sink's `RecordingHttpClient` pattern; assert URI, + NDJSON body shape, token header, and that emission is skipped when sampled out. + +## 15. Rollout and verification + +1. Land collection + header emission behind the flag, off everywhere. Full CI gate. +2. Staging deploy with the flag on. Then the one deployment unknown, verified with a + single request through the production route: the fronting VCL delivery layer must + pass the appended Server-Timing through rather than overwrite it. Fallback if it + clobbers: a one-line VCL change on the delivery service, or mirroring the value to + `x-ts-timing` while that lands. +3. Production flag on. Confirm + `performance.getEntriesByType('navigation')[0].serverTiming` shows `ts-*` entries + in a real browser session; from that moment any RUM tooling on the page contains + the breakdown. +4. Land the row schema, sink, settings unwiring; sample at 1.0 during stall diagnosis; + then the pipe and dashboard. +5. Success criterion: the next stall window is attributable from one response header + or one dashboard query, with no live probing session. + +## 16. Overhead + +Roughly ten monotonic clock reads and one ~130-byte header per request; one sampled +HTTP POST after the response has fully streamed. No allocation in the hot path beyond +the one `Arc` at entry and the rendered header string at finalize. + +## 17. Risks and open questions + +- The fronting delivery layer's Server-Timing handling is unverified until the first + staging deploy (step 2 above). This is the only known external dependency. +- `time_elapsed_ms` semantics change from "unspecified" to "ts-total" on a datasource + that has never had a deployed writer; acceptable without rename. +- Body-phase capture requires threading the timings handle into the streaming closure + in `publisher.rs`; the exact seam is an implementation-plan detail, with the + constraint that a dropped handle (error paths, early client disconnect) must still + yield a valid row with null body-phase fields. +- The stall window itself remains unattributed until this ships. If it recurs first, + the bisection runbook from 2026-08-21 (cookie-free curl UA request, `.js` path + versus HTML path) is the fallback. From 77b92f403b0bbb2c18cde6ad7135cc251d8b0452 Mon Sep 17 00:00:00 2001 From: Jason Evans Date: Mon, 24 Aug 2026 12:56:18 -0500 Subject: [PATCH 2/5] 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 --- .../2026-08-24-request-phase-timing-design.md | 427 +++++++++++------- 1 file changed, 273 insertions(+), 154 deletions(-) diff --git a/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md b/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md index b7f9d7d2f..4787ff578 100644 --- a/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md +++ b/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md @@ -1,8 +1,8 @@ # Request phase timing: Server-Timing subtimings and access telemetry **Date:** 2026-08-24 -**Status:** Approved design, pending implementation plan. -**Scope:** `trusted-server-core`, Fastly and Axum adapters, `tinybird/` schema and pipes, +**Status:** Approved design, revised for review round 1, pending implementation plan. +**Scope:** `trusted-server-core`, Fastly and Axum adapters, `tinybird/` schema, performance dashboard (separate repo). --- @@ -31,13 +31,21 @@ about itself. ## 2. Goals -1. Every response attributes its own server time by phase, in a standard header that - browsers expose to JavaScript (`PerformanceResourceTiming.serverTiming`), so any RUM - tool the publisher already runs picks up the breakdown with zero integration work. +1. Every normal application response attributes its own server time by phase in a + standard header. Browsers expose the values to same-origin JavaScript via + `PerformanceResourceTiming.serverTiming`, so RUM tooling that reads that API can + surface the breakdown. Whether a given vendor or the publisher's own monitoring + extension actually collects it is verified separately in rollout; the publisher + extension needs a small change to render it. 2. The same numbers flow to Tinybird so we hold p50/p95/p99 per phase, per route class, per PoP, per deployed version, and a future stall window self-diagnoses in one query. -3. Zero cost to TTFB: collection is a handful of monotonic clock reads; telemetry - emission happens strictly after the last body byte. +3. No additional awaited I/O before first byte. The pre-send cost is a handful of + monotonic clock reads, one small allocation at entry, and rendering one header; + telemetry emission happens strictly after the last body byte. + +Scope note: phases cover the application lifecycle after T0. The `/health` and +`/_ts/debug/ja4` short-circuits, config-store open failures, and request-conversion +failures bypass the lifecycle and emit nothing. ## 3. Non-goals @@ -47,8 +55,9 @@ about itself. regardless of which filter runs; vendor identity stays out of headers and telemetry. - No Cloudflare or Spin emission wiring in v1. Core collection is adapter-neutral; those adapters can wire emission later without core changes. -- No rollup materialized views. The raw datasource plus one endpoint pipe is v1; - rollups only if panel latency demands them. +- No Tinybird endpoint pipe and no rollup materialized views in v1. Grafana queries the + datasource through the ClickHouse connector, matching the auction dashboards; rollups + only if panel latency demands them. - No sampling of the header. The header is all-traffic when enabled; only Tinybird rows sample. @@ -56,159 +65,243 @@ about itself. ``` adapter entry (T0) - | RequestTimings::new() -> request extensions + | RequestTimings::new() -> shared handle v -app construction ................ ts-appbuild (adapter) -pre-route request filters ....... ts-filter (adapter wrapper) -geo lookup (single, deduped) .... ts-geo (adapter; result stashed) -EC KV before send ............... ts-kv (core: ec/finalize.rs) -template cache lookup ........... ts-c2 (core: publisher.rs) -origin fetch to resp headers .... ts-origin (core: publisher.rs) +app construction ................ ts-appbuild (adapter) +pre-route request filters ....... ts-filter (adapter wrapper) +geo lookup (single, deduped) .... ts-geo (adapter; result carried forward) +template cache lookup ........... ts-template-cache (core: publisher.rs) +origin fetch to resp headers .... ts-origin (core: publisher.rs) +EC identity KV, pre-send ........ ts-kv (core: KV abstraction) | -finalize middleware: - append Server-Timing header ... ts-total + all recorded spans +send_edgezero_response, immediately before into_parts(): + mark_headers_ready() snapshot (unconditional) + append Server-Timing header (flag-gated, skipped on shared-cacheable responses) | headers committed; body streams - auction hold at seam .......... auction_wait_ms (row only) + auction hold at seam .......... auction_wait_ms (row only) stream duration, bytes ........ stream_ms, resp_bytes (row only) | post-send (adapter main): - sample gate -> one NDJSON row -> Tinybird Events API (best effort) + sample gate -> one NDJSON row -> Tinybird Events API + bounded response await, 2xx validated ``` -Collection is always-on and flag-free. Two independent flags gate emission: the header -(`observability.server_timing_enabled`) and the telemetry row (`tinybird.access_enabled`). +Collection is always-on and flag-free, including the `mark_headers_ready()` snapshot. +Two independent flags gate emission: the header (`observability.server_timing_enabled`) +and the telemetry row (`tinybird.access_enabled`). ## 5. `RequestTimings` (core) New module `crates/trusted-server-core/src/request_timing.rs`. -- `Phase`: a closed enum: `AppBuild`, `Filter`, `Geo`, `EcKv`, `Origin`, `C2Lookup`, - `AuctionWait`, `Stream`. Header rendering covers the first six plus the derived - total; the last two are row-only. -- Inner state: one fixed-size array of `Option` slots indexed by phase, plus - `t0: Instant`, plus `resp_bytes: Option`. Phases that repeat within a request - (geo, KV) accumulate by saturating addition into the same slot. -- Sharing: `RequestTimings` is a cheap-clone handle, `Arc>`. It must cross - three boundaries: request extensions (adapter entry to core handlers), the streaming - body closure (records body-phase spans after the response object has been handed - off), and the adapter's post-send emission read. A poisoned or contended lock must - never fail a request: all recording methods are infallible and drop the sample on - lock failure. +- `Phase`: a closed enum: `AppBuild`, `Filter`, `Geo`, `EcKv`, `Origin`, + `TemplateCacheLookup`, `AuctionWait`, `Stream`. Header rendering covers the first six + plus the stored total; the last two are row-only. +- Inner state: one fixed-size array of `Option` slots indexed by phase, + `t0: Instant`, `headers_ready_total: Option`, and + `resp_bytes: Option`. Phases that repeat within a request (geo, KV) accumulate + by saturating addition into the same slot. +- `mark_headers_ready()`: stores `t0.elapsed()` once at the response-commit boundary, + unconditionally, before either emission flag is consulted. The header renders this + stored value as `ts-total`; the telemetry row reads the same stored value as + `time_elapsed_ms`. The two surfaces cannot disagree, and the row stays correct when + the header flag is off. Full request duration is captured separately at row build as + `request_elapsed_ms` (`t0.elapsed()` after the body has streamed). +- Sharing: `RequestTimings` is a cheap-clone handle, `Arc>`. It crosses + three boundaries: adapter entry to core handlers, the streaming body closure (records + body-phase spans after the response object has been handed off), and the adapter's + post-send emission read. A poisoned or contended lock must never fail a request: all + recording methods are infallible and drop the sample on lock failure. - Recording API: `timings.record(Phase::Geo, dur)` and a scope guard `timings.span(Phase::Origin)` that records on drop. Guards use saturating duration math; a non-monotonic reading records zero rather than panicking. - Rendering: `server_timing_value(&self) -> Option` produces `ts-total;dur=41.2, ts-appbuild;dur=18.4, ts-filter;dur=9.1` with durations in - milliseconds at one decimal. Phases never recorded are omitted. `ts-total` is - elapsed-since-`t0` at render time, which by construction is the last mutation before - send. Returns `None` when nothing was recorded (defensive; `t0` always exists). + milliseconds at one decimal. Phases never recorded are omitted. Returns `None` when + `mark_headers_ready()` has not run. `Instant` is already used freely in the guest (`publisher.rs`, `auction/telemetry.rs`), so no new clock abstraction is needed. ## 6. Span taxonomy and recording sites -| Entry | Measures | Site | -| ------------- | ------------------------------------------------------------------------- | --------------------------------------------------------------------------------------- | -| `ts-total` | adapter entry (post health short-circuit) to header emission | derived at render | -| `ts-appbuild` | config-store open, Settings parse, orchestrator + registry + router build | Fastly `main.rs` around `open_trusted_server_config_store()` + `build_app_with_state()` | -| `ts-filter` | pre-route request filters, end to end (backend ensure, secret read, POST) | around `run_pre_route_filters` (`app.rs:751`) | -| `ts-geo` | geo hostcall (single after dedupe; accumulates if any path still repeats) | `build_ec_request_state` (`app.rs:410`) | -| `ts-kv` | EC identity KV operations before send | `ec/finalize.rs` ingest path, EC-route KV lookups | -| `ts-origin` | publisher backend send to response headers available (C1 hit or miss) | `publisher.rs` around the origin `send` (~line 4496) | -| `ts-c2` | template cache `lookup_or_reserve`, including the hit-path full-body read | `publisher.rs` around the lookup (~line 4391) | +| Entry | Measures | Site | +| ------------------- | ------------------------------------------------------------------------------------- | --------------------------------------------------------------------------------------- | +| `ts-total` | T0 to `mark_headers_ready()` at the response-commit boundary | stored snapshot | +| `ts-appbuild` | config-store open, Settings parse, orchestrator + registry + router build | Fastly `main.rs` around `open_trusted_server_config_store()` + `build_app_with_state()` | +| `ts-filter` | pre-route request filters, end to end (backend ensure, secret read, POST) | around `run_pre_route_filters` (`app.rs:751`) | +| `ts-geo` | geo hostcall (single after dedupe; accumulates if any path still repeats) | `build_ec_request_state` (`app.rs:410`) | +| `ts-kv` | EC identity KV operations before response send (see enumeration below) | the shared KV abstraction | +| `ts-origin` | publisher backend send to response headers available (read-through cache hit or miss) | `publisher.rs` around the origin `send` | +| `ts-template-cache` | template cache `lookup_or_reserve`, including the hit-path full-body read | `publisher.rs` around the lookup | + +Naming follows the completed template-cache terminology migration (`x-ts-template-cache` +is the emitted header on `main`; `c2` naming is retired). + +`ts-kv` is instrumented at the shared identity-graph/KV abstraction +(`KvIdentityGraph` and the platform KV store wrapper), not at individual call sites, so +new callers cannot silently escape the span. Included pre-send operations: EC +generation `create_or_revive`, identify-path graph reads and evaluation, finalize-path +`ingest_eid_cookies`/`upsert_partner_ids` and withdrawal tombstones, consent-store +reads on consent routes, and batch-sync graph access when it runs before send. +Explicitly excluded: pull-sync work, which runs strictly after `send_to_client` and is +invisible to both surfaces. The timings handle reaches `ec_finalize_response` through +an existing context or a parameter object; that function already has the repository +maximum of seven arguments and does not gain an eighth. Row-only fields: -| Field | Measures | Site | -| ----------------- | -------------------------------------------------------- | ------------------------------------------------- | -| `auction_wait_ms` | hold at the `` seam waiting on dispatched auction | `collect_stream_auction` / seam wait in publisher | -| `stream_ms` | headers committed to last body byte | adapter around the body-stream drive | -| `resp_bytes` | bytes written to the client body | same | - -## 7. Header emission - -The last step of `apply_finalize_headers` (`middleware.rs:197`) appends one -`Server-Timing` header from `server_timing_value()`, gated on -`observability.server_timing_enabled`. Append semantics, never insert: an -origin-supplied Server-Timing survives, and the fronting delivery layer's own entries -(`time-elapsed`, `hit-state`) are additive per the header's list semantics. - -Emission runs after the finalize geo resolution and after every configurable response -mutation, so the header reflects everything that happened before send. Both finalize -sites (the router middleware and the adapter entry-point fallback for streaming -responses) emit through the same helper; the `HEADER_X_TS_FINALIZED` marker already -prevents double-finalization, which also prevents a doubled header. +| Field | Measures | Site | +| -------------------- | -------------------------------------------------------- | ------------------------------------------------- | +| `auction_wait_ms` | hold at the `` seam waiting on dispatched auction | `collect_stream_auction` / seam wait in publisher | +| `stream_ms` | headers committed to last body byte | adapter around the body-stream drive | +| `resp_bytes` | bytes written to the client body | same | +| `request_elapsed_ms` | T0 to row build (full request duration, post-body) | row assembly | + +`auction_wait_ms` is nested inside `stream_ms`. Queries and panels must never stack or +sum them as siblings; the derived quantities are `stream_other_ms = stream_ms - +auction_wait_ms` and `unattributed_ms = max(time_elapsed_ms - (appbuild + filter + geo + +- kv + origin + template_cache), 0)`, computed at query time. + +## 7. Freeze point and header emission + +The freeze-and-emit point is `send_edgezero_response` (Fastly `main.rs`), immediately +before `response.into_parts()`. This is the single choke point every send path shares, +and it runs after everything that can still mutate the response: the router middleware, +entry-point finalize (`apply_finalize_headers`, asset-policy reapplication), EC +finalization and its KV work, and terminal filter/privacy effects. +`apply_finalize_headers` itself does not emit; the `HEADER_X_TS_FINALIZED` sentinel +marks middleware finalization, not header commitment, and must not be treated as the +timing boundary. + +At the freeze point, in order: `mark_headers_ready()` (unconditional), then, gated on +`observability.server_timing_enabled`, append one `Server-Timing` header from +`server_timing_value()`. Append semantics, never insert: an origin-supplied +Server-Timing survives, and the fronting delivery layer's own entries (`time-elapsed`, +`hit-state`) are additive per the header's list semantics. + +Header emission is skipped when the response is shared-cacheable (a public +`Cache-Control` with positive freshness, or any surrogate/CDN cache directive): a +shared cache would replay one request's timings for the object's full TTL. The +long-lived immutable `tsjs` asset route is the concrete case. The snapshot and the +telemetry row are unaffected by this skip. + +The Axum adapter applies the same rule at its equivalent last point before response +serialization, using the same core helper. ## 8. Geo lookup dedupe (rider) Today every dispatched request pays two geo hostcalls for one answer: request-phase in `build_ec_request_state` (`app.rs:410`) and response-phase in -`FinalizeResponseMiddleware` (`middleware.rs:83`, alternate site `main.rs:285`). The -first lookup stashes the resolved `GeoInfo` in request extensions; the finalize path -reads the stashed value and only falls back to a live lookup when the request-phase -never ran. This halves exposure to a degraded geo subsystem, which is one of the three -candidate dependencies for the observed stall window. The 401 short-circuit behavior +`FinalizeResponseMiddleware` (`middleware.rs:83`, alternate site `main.rs:285`). + +Plain request extensions cannot carry the result out: the middleware moves the request +context into `next.run(ctx)` and holds only the response afterward. The resolved geo +travels instead through the response path, either on the existing `EcFinalizeState` +response extension or a dedicated response extension installed by the dispatch layer, +as a three-state value: `NotAttempted`, `Attempted(None)` (lookup ran and failed, do +not retry), and `Resolved(GeoInfo)`. The finalize path consumes the carried value and +performs a live lookup only in the `NotAttempted` state. The 401 rule (`resolve_geo_for_response` skips lookup for unauthorized responses) is preserved. ## 9. Access telemetry row -Extends the reserved `tinybird/datasources/access_logs_raw.datasource` (in-repo only, -no deployed pipes over it, so this is an edit rather than a migration). +Extends the reserved `tinybird/datasources/access_logs_raw.datasource`. + +Kept columns: `event_ts`, `method`, `status`, `time_elapsed_ms` (defined as the +`mark_headers_ready()` snapshot), `cache_state`, `country`, `sample_rate`, +`event_date`, 30-day TTL. -Kept columns: `event_ts`, `method`, `path`, `status`, `time_elapsed_ms` (now defined as -`ts-total`), `cache_state`, `country`, `sample_rate`, `event_date`, 30-day TTL. +Removed: raw `path`. Route identifiers like `/_ts/admin/ec/{id}` would otherwise put +EC identifiers into a 30-day dataset, and publisher paths carry unbounded cardinality. +Replaced by `route_template`: for named routes, the matched route-table pattern +verbatim (parameters stay as placeholders); for the publisher fallback, the bounded +normalized form produced by the existing auction-telemetry path normalizer. A +serialization test proves a literal EC identifier never appears in an emitted row. Added columns: ``` -`route_class` LowCardinality(String), -- publisher_html | tsjs | integration_proxy | ec | auction_api | other -`appbuild_ms` Nullable(UInt32), -`filter_ms` Nullable(UInt32), -`geo_ms` Nullable(UInt32), -`kv_ms` Nullable(UInt32), -`origin_ms` Nullable(UInt32), -`c2_ms` Nullable(UInt32), -`auction_wait_ms` Nullable(UInt32), -`stream_ms` Nullable(UInt32), -`resp_bytes` Nullable(UInt64), -`c2_state` LowCardinality(Nullable(String)), -- x-ts-c2-cache value -`ts_version` LowCardinality(String), -`pop` LowCardinality(Nullable(String)) -- FASTLY_POP +`publisher_domain` LowCardinality(String), -- row identity, matches auction schema +`env` LowCardinality(String), -- x-ts-env value +`route_class` LowCardinality(String), -- publisher_html | tsjs | integration_proxy | ec | auction_api | other +`route_template` String, -- bounded, normalized; replaces path +`appbuild_ms` Nullable(UInt32), +`filter_ms` Nullable(UInt32), +`geo_ms` Nullable(UInt32), +`kv_ms` Nullable(UInt32), +`origin_ms` Nullable(UInt32), +`template_cache_ms` Nullable(UInt32), +`auction_wait_ms` Nullable(UInt32), +`stream_ms` Nullable(UInt32), +`request_elapsed_ms` Nullable(UInt32), +`resp_bytes` Nullable(UInt64), +`template_cache_state` LowCardinality(Nullable(String)), -- x-ts-template-cache value +`ts_version` LowCardinality(String), +`pop` LowCardinality(Nullable(String)) -- FASTLY_POP ``` Null means the phase did not run. `route_class` is assigned by the adapter at handler -selection (the named-route table knows which handler it picked), not by path regex. -Percentile analysis groups by `route_class`; `path` stays for drill-down only. +selection, not by path regex. `ts_version` plus `pop` is not globally unique across +deployments; `publisher_domain` plus `env` provides row identity. + +Sorting key: `(event_date, publisher_domain, route_class, pop, status)`, aligned with +the analysis dimensions. This replaces the reserved key +`(event_date, path, status, method)`. Rollout step 4 verifies whether the reserved +datasource was ever deployed to the remote workspace; if it was, this schema ships as +a versioned replacement datasource with a cutover, not an in-place edit. ## 10. Emission mechanics - Point: Fastly `main.rs`, strictly after `send_edgezero_response` returns (the body has fully streamed). The row can never affect TTFB or block delivery. - Sampling: uniform per-request decision against `tinybird.access_sample_rate` - (validation `0.0..=1.0` already exists). No client stickiness. -- Transport: one NDJSON row to the Tinybird Events API, mirroring the auction sink - (`tinybird.rs`): same `api_host`, reserved `access_dataset` and - `access_token_secret`, 2 s first-byte and between-bytes timeouts, `max_body_bytes` - guard, best-effort with a warn log on failure, no retry. + (validation `0.0..=1.0` already exists). No client stickiness. Sampled-out requests + are silent; every other drop (row build failure, send failure, non-2xx) logs a + warning naming the reason, so lost diagnostic rows are visible. +- Transport: one NDJSON row to the Tinybird Events API: same `api_host`, reserved + `access_dataset` and `access_token_secret`, 2 s first-byte and between-bytes + timeouts, `max_body_bytes` guard, no retry. +- Delivery confirmation: unlike the auction sink, which starts `send_async` and drops + the pending response (it runs before delivery completes and cannot afford to wait), + the access emitter runs after the client has the full response and therefore awaits + the bounded ingest response and validates 2xx. A non-2xx or timeout logs a warning + with the status. This is what makes the warning semantics real rather than + aspirational. +- Budget: at `access_sample_rate = 1.0` this adds one backend request per request to + the service, after delivery. The sample rate is the budget control; 1.0 is a + diagnosis setting, not a steady state. - Settings: the guard that rejects `tinybird.access_enabled = true` "until an emitter - is wired" (`settings.rs:4123` test) flips into a wiring test in the same change, so - the flag and the emitter land together. `access_enabled = true` requires - `tinybird.enabled` and a non-empty `api_host`. -- Axum adapter: emits the header via the same core helper; does not emit Tinybird rows - in v1 (local dev has no Tinybird backend; the sink stays behind the Fastly adapter). - -## 11. Pipe and dashboard - -- `tinybird/pipes/access_phase_stats.pipe`: endpoint returning p50/p95/p99 of each - phase column grouped by `route_class` and hour, filterable by `pop` and `ts_version`. -- Dashboard: a new standalone `grafana/dashboards/edge-performance.json` in the - telemetry repo (`trusted-server-tinybird`), performance only, no panels shared with - the revenue and auction dashboards. Panels: phase percentiles by route class, stacked - phase breakdown over time, PoP split, version overlay, C2 hit-rate, and a stall - panel: rows with `time_elapsed_ms > 500` grouped by dominant phase. Queries hit the - raw datasource with `$__timeFilter(event_ts)`. + is wired" flips into a wiring test in the same change. `access_enabled = true` + requires `tinybird.enabled` and a non-empty `api_host`. +- Axum adapter: emits the header only; no Tinybird rows in v1. + +## 11. Dashboard and query model + +No endpoint pipe in v1. Grafana queries `access_logs_raw` directly through the +ClickHouse connector with `$__timeFilter(event_ts)`, matching the auction dashboards. + +Dashboard: a new standalone `grafana/dashboards/edge-performance.json` in the +telemetry repo (`trusted-server-tinybird`), performance only, no panels shared with +the revenue and auction dashboards. Panels: + +- Phase percentiles (p50/p95/p99) by `route_class`, per phase column. +- Stacked phase breakdown over time using the non-overlapping set: `appbuild_ms`, + `filter_ms`, `geo_ms`, `kv_ms`, `origin_ms`, `template_cache_ms`, and derived + `unattributed_ms`. `auction_wait_ms` and derived `stream_other_ms` chart in a + separate body-phase panel and never stack with pre-header phases. +- PoP split, `ts_version` overlay, template-cache state rates. +- Stall panel: rows with `request_elapsed_ms > 500` (post-body total, so body-only + stalls are caught) grouped by dominant phase, where `unattributed_ms` competes as a + phase so the panel cannot confidently blame a small measured span while most time is + uninstrumented. + +Sampling semantics for every aggregate: `sample_rate` must be operationally stable +within any queried window. Panels either filter to a single `sample_rate` value or +apply inverse-probability weights (`count() * 1/sample_rate`) for volume panels; +pooled unweighted quantiles across a rate change are documented as invalid. ## 12. Config surface @@ -216,72 +309,98 @@ Percentile analysis groups by `route_class`; `path` stays for drill-down only. [observability] # Append TS phase timings to the Server-Timing response header. server_timing_enabled = false # example default - -[tinybird] -access_enabled = false # requires tinybird.enabled and api_host when true -access_sample_rate = 0.0 # 1.0 during active diagnosis, dial down after ``` New `ObservabilitySettings` struct with the single boolean, default off, standard environment override (`TRUSTED_SERVER__OBSERVABILITY__SERVER_TIMING_ENABLED`). Collection has no flag: the flags gate the two emission surfaces independently. +Rollback and compatibility, because `Settings` is `deny_unknown_fields`: + +- Deployment order is binary first, config second. Rollback order is config first + (remove the `[observability]` table), binary second. A config containing the table + must never be pushed while a pre-observability binary can still run. +- Config serialization omits the table when it equals the default, so round-tripping a + config through tooling does not inject a field an older binary rejects. A + compatibility test asserts the serialized default config parses under the previous + schema. +- The environment-variable overlay cannot create a missing leaf, so the key ships + present-but-false in the base operator TOML (the same pattern the GPT integration + documents in `trusted-server.example.toml`) and is flipped by config push. + +`[tinybird]` gains no new keys; `access_enabled` and `access_sample_rate` are already +reserved. + ## 13. Error handling - Recording is infallible: saturating math, lock-failure drops the sample, no panics. -- Header rendering failure (invalid header value cannot occur with the fixed format; - defensive `HeaderValue::from_str` error) logs and skips the header. -- Row emission failure logs a warning and drops the row. The response has already been - delivered; there is nothing to degrade. +- Header rendering failure (defensive `HeaderValue::from_str` error) logs and skips + the header. +- Row emission failure logs a warning naming the reason and drops the row. The + response has already been delivered; there is nothing to degrade. ## 14. Testing -- Core unit tests: phase accumulation, saturating math, render format (one decimal, - omission of unrecorded phases, `ts-total` presence), row serialization shape. +- Core unit tests: phase accumulation, saturating math, `mark_headers_ready()` + idempotence and both-surface consistency, render format (one decimal, omission of + unrecorded phases), row serialization shape. - Adapter tests (Fastly via Viceroy, Axum native): header present and well-formed on a - publisher route and on the tsjs route with the flag on; absent with the flag off; - exactly one header after both finalize paths; append preserves a pre-existing - Server-Timing value. -- Geo dedupe: finalize consumes the stashed request-phase `GeoInfo`; live-lookup - fallback fires when the request phase never ran; 401 skip preserved. -- Settings: `access_enabled` validation matrix (requires `tinybird.enabled`, - `api_host`); the former rejection test becomes the wiring test. -- Sink tests: mirror the auction sink's `RecordingHttpClient` pattern; assert URI, - NDJSON body shape, token header, and that emission is skipped when sampled out. + publisher route with the flag on; absent with the flag off; absent on a + shared-cacheable response (tsjs route) with the flag on; exactly one header across + all send paths; append preserves a pre-existing Server-Timing value; `ts-kv` + captures EC finalize work (proving the freeze point sits after it). +- Geo dedupe: finalize consumes `Resolved`; no retry on `Attempted(None)`; live + lookup only on `NotAttempted`; 401 skip preserved. +- Route template: serialization test proving a literal EC identifier never appears in + a row for the admin EC route; publisher fallback paths normalize to bounded output. +- Settings: `access_enabled` validation matrix; the former rejection test becomes the + wiring test; the serialized-default-config compatibility test against the previous + schema. +- Sink tests: `RecordingHttpClient` pattern; assert URI, NDJSON body shape, token + header, 2xx validation and warning on non-2xx, skip when sampled out. ## 15. Rollout and verification -1. Land collection + header emission behind the flag, off everywhere. Full CI gate. -2. Staging deploy with the flag on. Then the one deployment unknown, verified with a - single request through the production route: the fronting VCL delivery layer must - pass the appended Server-Timing through rather than overwrite it. Fallback if it - clobbers: a one-line VCL change on the delivery service, or mirroring the value to +1. Land collection + freeze point + header emission behind the flag, off everywhere. + Full CI gate. +2. Staging deploy with the flag on. Then the delivery-layer check, verified with a + single request through the production route: the fronting VCL layer must pass the + appended Server-Timing through rather than overwrite it. Fallback if it clobbers: a + one-line VCL change on the delivery service, or mirroring the value to `x-ts-timing` while that lands. 3. Production flag on. Confirm `performance.getEntriesByType('navigation')[0].serverTiming` shows `ts-*` entries - in a real browser session; from that moment any RUM tooling on the page contains - the breakdown. -4. Land the row schema, sink, settings unwiring; sample at 1.0 during stall diagnosis; - then the pipe and dashboard. + in a real browser session, and separately confirm what the publisher's RUM tooling + actually collects; the publisher monitoring extension renders it only after a small + change on their side. +4. Verify whether `access_logs_raw` exists in the remote Tinybird workspace. If yes, + ship the schema as a versioned replacement with cutover; if no, edit in place. Then + land the row schema, sink, and settings unwiring; sample at 1.0 during stall + diagnosis; then the dashboard. 5. Success criterion: the next stall window is attributable from one response header or one dashboard query, with no live probing session. ## 16. Overhead -Roughly ten monotonic clock reads and one ~130-byte header per request; one sampled -HTTP POST after the response has fully streamed. No allocation in the hot path beyond -the one `Arc` at entry and the rendered header string at finalize. - -## 17. Risks and open questions - -- The fronting delivery layer's Server-Timing handling is unverified until the first - staging deploy (step 2 above). This is the only known external dependency. -- `time_elapsed_ms` semantics change from "unspecified" to "ts-total" on a datasource - that has never had a deployed writer; acceptable without rename. -- Body-phase capture requires threading the timings handle into the streaming closure - in `publisher.rs`; the exact seam is an implementation-plan detail, with the - constraint that a dropped handle (error paths, early client disconnect) must still - yield a valid row with null body-phase fields. +Roughly ten monotonic clock reads, one stored snapshot, and one ~130-byte header per +request; one sampled HTTP POST with a bounded await after the response has fully +streamed. No allocation in the hot path beyond the one `Arc` at entry and the rendered +header string at the freeze point. + +## 17. Decisions and open questions + +- **Public exposure is a decision, not an open question.** The header is all-traffic + when enabled. Rationale: values are durations only; the delivery layer already + exposes `hit-state` and `time-elapsed` publicly on every response; filter vendor + identity is masked; shared-cacheable responses are excluded from emission so a cache + cannot replay stale timings. Revisit (quantization or gating) only if a concrete + abuse surfaces. +- The fronting delivery layer's Server-Timing pass-through is unverified until the + first staging deploy (step 2). This is the only known external dependency. +- Body-phase capture threads the timings handle into the streaming closure in + `publisher.rs`; the exact seam is an implementation-plan detail, with the constraint + that a dropped handle (error paths, early client disconnect) must still yield a + valid row with null body-phase fields. - The stall window itself remains unattributed until this ships. If it recurs first, - the bisection runbook from 2026-08-21 (cookie-free curl UA request, `.js` path - versus HTML path) is the fallback. + the bisection runbook from 2026-08-21 (cookie-free curl UA request, static-asset + path versus HTML path) is the fallback. From 5557ff8d0debaec2bc2a2f0389f5f3995564d9d1 Mon Sep 17 00:00:00 2001 From: Jason Evans Date: Mon, 24 Aug 2026 13:29:25 -0500 Subject: [PATCH 3/5] 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 --- .../2026-08-24-request-phase-timing-design.md | 344 ++++++++++++------ 1 file changed, 231 insertions(+), 113 deletions(-) diff --git a/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md b/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md index 4787ff578..96bdb3617 100644 --- a/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md +++ b/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md @@ -1,7 +1,8 @@ # Request phase timing: Server-Timing subtimings and access telemetry **Date:** 2026-08-24 -**Status:** Approved design, revised for review round 1, pending implementation plan. +**Status:** Approved design, revised for review rounds 1 and 2, pending implementation +plan. **Scope:** `trusted-server-core`, Fastly and Axum adapters, `tinybird/` schema, performance dashboard (separate repo). @@ -9,8 +10,8 @@ performance dashboard (separate repo). ## 1. Problem -On 2026-08-21 a production deployment (publisher redacted, `prospect-a.com`) showed an -episodic stall: for a window of roughly 40 minutes, every request that reached the +On 2026-08-21 a production deployment (publisher redacted, `prospect-a.example`) showed +an episodic stall: for a window of roughly 40 minutes, every request that reached the application path carried a uniform extra ~600 ms of Fastly `time-elapsed`, and then recovered to 20-50 ms with no deploy or config change we could observe. `/health` (2-4 ms, short-circuits before app construction) and `/_ts/debug/ja4` (6-9 ms, settings @@ -25,9 +26,12 @@ POST, and EC identity KV writes before send), plus one dependency shared by ever application route (two geo hostcalls per request). We could not tell which one stalled, because nothing in the response says where server time went. -The Compute CPU budget is ~50 ms per request, so any large `time-elapsed` is wall-clock -await on a dependency by definition. Those are exactly the numbers a response can carry -about itself. +The Compute CPU budget is ~50 ms per request, so a large `time-elapsed` strongly +suggests wall-clock time outside active guest CPU: dependency awaits are the leading +explanation, with platform scheduling and hostcall queueing as the residual ones. The +comparison figure here is the fronting delivery layer's `time-elapsed` Server-Timing +entry, observed at its deliver phase. Either way, these are exactly the numbers a +response can carry about itself. ## 2. Goals @@ -45,7 +49,8 @@ about itself. Scope note: phases cover the application lifecycle after T0. The `/health` and `/_ts/debug/ja4` short-circuits, config-store open failures, and request-conversion -failures bypass the lifecycle and emit nothing. +failures bypass the lifecycle and emit nothing. Requests served entirely by the +fronting cache never reach the guest and produce neither header entries nor rows. ## 3. Non-goals @@ -60,6 +65,9 @@ failures bypass the lifecycle and emit nothing. only if panel latency demands them. - No sampling of the header. The header is all-traffic when enabled; only Tinybird rows sample. +- No cross-request circuit breaker for telemetry emission. Compute runs one isolate per + request; there is no shared mutable state to hold breaker state. The controls are the + bounded per-request cost and the `access_sample_rate` lever (section 10). ## 4. Design overview @@ -73,16 +81,19 @@ geo lookup (single, deduped) .... ts-geo (adapter; result carried fo template cache lookup ........... ts-template-cache (core: publisher.rs) origin fetch to resp headers .... ts-origin (core: publisher.rs) EC identity KV, pre-send ........ ts-kv (core: KV abstraction) +auction wait, buffered mode ..... auction_wait_ms (row only; pre-header in this mode) | send_edgezero_response, immediately before into_parts(): mark_headers_ready() snapshot (unconditional) - append Server-Timing header (flag-gated, skipped on shared-cacheable responses) + build AccessTelemetrySnapshot (unconditional) + append Server-Timing header (flag-gated, only on conclusively private responses) | headers committed; body streams - auction hold at seam .......... auction_wait_ms (row only) + auction hold at seam .......... auction_wait_ms (row only; in-stream in this mode) stream duration, bytes ........ stream_ms, resp_bytes (row only) | post-send (adapter main): + request_elapsed snapshot, then existing pull-sync, then: sample gate -> one NDJSON row -> Tinybird Events API bounded response await, 2xx validated ``` @@ -99,15 +110,18 @@ New module `crates/trusted-server-core/src/request_timing.rs`. `TemplateCacheLookup`, `AuctionWait`, `Stream`. Header rendering covers the first six plus the stored total; the last two are row-only. - Inner state: one fixed-size array of `Option` slots indexed by phase, - `t0: Instant`, `headers_ready_total: Option`, and - `resp_bytes: Option`. Phases that repeat within a request (geo, KV) accumulate - by saturating addition into the same slot. + `t0: Instant`, `headers_ready_total: Option`, + `auction_wait_placement: Option` (`PreHeader` or `InStream`), + and `resp_bytes: Option`. Phases that repeat within a request (geo, KV) + accumulate by saturating addition into the same slot. - `mark_headers_ready()`: stores `t0.elapsed()` once at the response-commit boundary, unconditionally, before either emission flag is consulted. The header renders this stored value as `ts-total`; the telemetry row reads the same stored value as `time_elapsed_ms`. The two surfaces cannot disagree, and the row stays correct when - the header flag is off. Full request duration is captured separately at row build as - `request_elapsed_ms` (`t0.elapsed()` after the body has streamed). + the header flag is off. Full request duration is captured separately as + `request_elapsed_ms`, snapshotted immediately after the body-stream drive returns and + before any other post-send work, so pull-sync and telemetry emission are never + included in it. - Sharing: `RequestTimings` is a cheap-clone handle, `Arc>`. It crosses three boundaries: adapter entry to core handlers, the streaming body closure (records body-phase spans after the response object has been handed off), and the adapter's @@ -115,7 +129,8 @@ New module `crates/trusted-server-core/src/request_timing.rs`. recording methods are infallible and drop the sample on lock failure. - Recording API: `timings.record(Phase::Geo, dur)` and a scope guard `timings.span(Phase::Origin)` that records on drop. Guards use saturating duration - math; a non-monotonic reading records zero rather than panicking. + math; a non-monotonic reading records zero rather than panicking. The auction-wait + recorder takes the placement explicitly so the two modes cannot be conflated. - Rendering: `server_timing_value(&self) -> Option` produces `ts-total;dur=41.2, ts-appbuild;dur=18.4, ts-filter;dur=9.1` with durations in milliseconds at one decimal. Phases never recorded are omitted. Returns `None` when @@ -131,7 +146,7 @@ so no new clock abstraction is needed. | `ts-total` | T0 to `mark_headers_ready()` at the response-commit boundary | stored snapshot | | `ts-appbuild` | config-store open, Settings parse, orchestrator + registry + router build | Fastly `main.rs` around `open_trusted_server_config_store()` + `build_app_with_state()` | | `ts-filter` | pre-route request filters, end to end (backend ensure, secret read, POST) | around `run_pre_route_filters` (`app.rs:751`) | -| `ts-geo` | geo hostcall (single after dedupe; accumulates if any path still repeats) | `build_ec_request_state` (`app.rs:410`) | +| `ts-geo` | geo hostcall (single after dedupe; accumulates if any path still repeats) | `build_ec_request_state` (`app.rs:410`) and timed finalizer fallback lookups | | `ts-kv` | EC identity KV operations before response send (see enumeration below) | the shared KV abstraction | | `ts-origin` | publisher backend send to response headers available (read-through cache hit or miss) | `publisher.rs` around the origin `send` | | `ts-template-cache` | template cache `lookup_or_reserve`, including the hit-path full-body read | `publisher.rs` around the lookup | @@ -152,18 +167,31 @@ maximum of seven arguments and does not gain an eighth. Row-only fields: -| Field | Measures | Site | -| -------------------- | -------------------------------------------------------- | ------------------------------------------------- | -| `auction_wait_ms` | hold at the `` seam waiting on dispatched auction | `collect_stream_auction` / seam wait in publisher | -| `stream_ms` | headers committed to last body byte | adapter around the body-stream drive | -| `resp_bytes` | bytes written to the client body | same | -| `request_elapsed_ms` | T0 to row build (full request duration, post-body) | row assembly | - -`auction_wait_ms` is nested inside `stream_ms`. Queries and panels must never stack or -sum them as siblings; the derived quantities are `stream_other_ms = stream_ms - -auction_wait_ms` and `unattributed_ms = max(time_elapsed_ms - (appbuild + filter + geo - -- kv + origin + template_cache), 0)`, computed at query time. +| Field | Measures | Site | +| -------------------- | --------------------------------------------------------- | ------------------------------------------------ | +| `auction_wait_ms` | wait on the dispatched auction (placement varies by mode) | seam hold (streaming) or buffered finalizer wait | +| `body_mode` | `streamed` or `buffered` response assembly | set where the response body is built | +| `stream_ms` | headers committed to last body byte | adapter around the body-stream drive | +| `resp_bytes` | bytes written to the client body | same | +| `request_elapsed_ms` | T0 to immediately after the body-stream drive returns | post-send snapshot, before pull-sync | + +Auction-wait placement is not universal. On the ordinary streaming path the wait +happens at the `` seam inside the body stream and nests inside `stream_ms`. On +buffered paths (the Fastly shared-template authorized miss, which buffers the full +transform and auction before returning a response, and every Axum response) the wait +completes before headers commit. The row therefore carries `body_mode` plus +`auction_wait_placement` (`pre_header` or `in_stream`), and derivations are +conditional: + +- `in_stream`: `stream_other_ms = greatest(coalesce(stream_ms, 0) - coalesce(auction_wait_ms, 0), 0)`. +- `pre_header`: `auction_wait_ms` joins the pre-header phase set, and `stream_other_ms = coalesce(stream_ms, 0)`. + +`unattributed_ms = greatest(coalesce(time_elapsed_ms, 0) - (coalesce(appbuild_ms, 0) + +coalesce(filter_ms, 0) + coalesce(geo_ms, 0) + coalesce(kv_ms, 0) + +coalesce(origin_ms, 0) + coalesce(template_cache_ms, 0) + pre-header auction wait), 0)`. +Every phase column is nullable, so every query-time formula wraps each term in +`coalesce(column, 0)` and every subtraction in `greatest(..., 0)`; query tests cover +sparse phase combinations. ## 7. Freeze point and header emission @@ -176,20 +204,25 @@ finalization and its KV work, and terminal filter/privacy effects. marks middleware finalization, not header commitment, and must not be treated as the timing boundary. -At the freeze point, in order: `mark_headers_ready()` (unconditional), then, gated on +At the freeze point, in order: `mark_headers_ready()` (unconditional), the +`AccessTelemetrySnapshot` build (unconditional, section 10), then, gated on `observability.server_timing_enabled`, append one `Server-Timing` header from `server_timing_value()`. Append semantics, never insert: an origin-supplied Server-Timing survives, and the fronting delivery layer's own entries (`time-elapsed`, `hit-state`) are additive per the header's list semantics. -Header emission is skipped when the response is shared-cacheable (a public -`Cache-Control` with positive freshness, or any surrogate/CDN cache directive): a -shared cache would replay one request's timings for the object's full TTL. The -long-lived immutable `tsjs` asset route is the concrete case. The snapshot and the -telemetry row are unaffected by this skip. +Header emission is conservative: it happens only when the response is conclusively +non-storable by any shared cache, meaning `Cache-Control` contains `private` or +`no-store` (the existing `cache_control_headers_are_private_or_no_store` predicate). +Anything else, including bare `max-age`, `s-maxage` without `private`, +heuristically-cacheable responses with no cache header at all, and anything a fronting +cache override might store, emits no header, because a stored object would replay one +request's timings for its full lifetime. The long-lived immutable `tsjs` asset route +is the concrete excluded case. The snapshot and the telemetry row are unaffected by +this skip, so excluded routes still report through Tinybird. -The Axum adapter applies the same rule at its equivalent last point before response -serialization, using the same core helper. +The Axum adapter applies the same emission rule at its terminal point before response +serialization, with adapter-specific phase semantics (section 8a). ## 8. Geo lookup dedupe (rider) @@ -199,35 +232,66 @@ Today every dispatched request pays two geo hostcalls for one answer: request-ph Plain request extensions cannot carry the result out: the middleware moves the request context into `next.run(ctx)` and holds only the response afterward. The resolved geo -travels instead through the response path, either on the existing `EcFinalizeState` -response extension or a dedicated response extension installed by the dispatch layer, -as a three-state value: `NotAttempted`, `Attempted(None)` (lookup ran and failed, do -not retry), and `Resolved(GeoInfo)`. The finalize path consumes the carried value and -performs a live lookup only in the `NotAttempted` state. The 401 rule -(`resolve_geo_for_response` skips lookup for unauthorized responses) is preserved. +travels on a dedicated `GeoLookupState` response extension, attached on every exit +path that attempted a lookup, including the asset fallback, which runs +`build_ec_request_state` and then returns without `EcFinalizeState` (which is why +`EcFinalizeState` is not an acceptable carrier). States: `NotAttempted`, +`Attempted(None)` (lookup ran and failed, do not retry), and `Resolved(GeoInfo)`. The +finalize path consumes the carried value and performs a live lookup only in the +`NotAttempted` state; those legitimate fallback lookups (admin, batch, error paths) +are themselves timed into `ts-geo` so degraded geo cannot hide inside +`unattributed_ms`. The 401 rule (`resolve_geo_for_response` skips lookup for +unauthorized responses) is preserved. + +## 8a. Adapter phase semantics + +The Fastly adapter is the reference implementation of the taxonomy. Axum differs +structurally and its emissions are defined accordingly rather than pretending parity: + +- `ts-appbuild` is absent: Axum builds application state once at startup. +- `body_mode` is always `buffered`: the Axum HTTP client buffers upstream bodies, so + `stream_ms` measures buffered-body write-out and `auction_wait_placement` is always + `pre_header`. +- The freeze point is an Axum-terminal middleware layer that runs after all response + mutation, covering router-generated 404/405 responses; Axum's `/health` sits inside + the middleware stack and is excluded explicitly by route match. +- Axum emits the header only; no Tinybird rows in v1 (unchanged). + +Cloudflare and Spin: collection compiles, no emission wiring in v1 (unchanged). ## 9. Access telemetry row Extends the reserved `tinybird/datasources/access_logs_raw.datasource`. Kept columns: `event_ts`, `method`, `status`, `time_elapsed_ms` (defined as the -`mark_headers_ready()` snapshot), `cache_state`, `country`, `sample_rate`, -`event_date`, 30-day TTL. +`mark_headers_ready()` snapshot), `sample_rate`, `event_date`, 30-day TTL. Removed: raw `path`. Route identifiers like `/_ts/admin/ec/{id}` would otherwise put -EC identifiers into a 30-day dataset, and publisher paths carry unbounded cardinality. -Replaced by `route_template`: for named routes, the matched route-table pattern -verbatim (parameters stay as placeholders); for the publisher fallback, the bounded -normalized form produced by the existing auction-telemetry path normalizer. A -serialization test proves a literal EC identifier never appears in an emitted row. - -Added columns: +EC identifiers into a 30-day dataset, and publisher paths carry unbounded cardinality +and user-generated content (search terms, usernames, emails in slugs). Replaced by +`route_template`: + +- Named routes: the matched route-table pattern verbatim, parameters left as + placeholders. +- Publisher fallback: a coarse fixed template, `/` plus the first path segment + restricted to a bounded allowlisted charset, plus `/*` when deeper (for example + `/news/*`). The auction-telemetry normalizer is explicitly not sufficient here: it + redacts long tokens but preserves short identifiers and arbitrary slugs. +- Tests are adversarial, not just the happy path: a literal EC identifier on the admin + route, an email address in a path segment, search-term-shaped segments, and + overlong segments must all normalize to bounded, content-free templates. + +Added columns (all dimension columns non-nullable with an `unknown` sentinel, because +ClickHouse sorting keys cannot contain nullable columns): ``` -`publisher_domain` LowCardinality(String), -- row identity, matches auction schema -`env` LowCardinality(String), -- x-ts-env value +`service_id` LowCardinality(String), -- FASTLY_SERVICE_ID; immutable deployment identity +`publisher_domain` LowCardinality(String), -- matches auction schema +`env` LowCardinality(String), -- from typed settings state, never from a response header `route_class` LowCardinality(String), -- publisher_html | tsjs | integration_proxy | ec | auction_api | other `route_template` String, -- bounded, normalized; replaces path +`body_mode` LowCardinality(String), -- streamed | buffered +`auction_wait_placement` LowCardinality(String), -- pre_header | in_stream | none `appbuild_ms` Nullable(UInt32), `filter_ms` Nullable(UInt32), `geo_ms` Nullable(UInt32), @@ -238,29 +302,55 @@ Added columns: `stream_ms` Nullable(UInt32), `request_elapsed_ms` Nullable(UInt32), `resp_bytes` Nullable(UInt64), -`template_cache_state` LowCardinality(Nullable(String)), -- x-ts-template-cache value +`template_cache_state` LowCardinality(String), -- from the typed response extension, not the public header +`country` LowCardinality(String), `ts_version` LowCardinality(String), -`pop` LowCardinality(Nullable(String)) -- FASTLY_POP +`pop` LowCardinality(String) -- FASTLY_POP, 'unknown' when absent ``` -Null means the phase did not run. `route_class` is assigned by the adapter at handler -selection, not by path regex. `ts_version` plus `pop` is not globally unique across -deployments; `publisher_domain` plus `env` provides row identity. - -Sorting key: `(event_date, publisher_domain, route_class, pop, status)`, aligned with -the analysis dimensions. This replaces the reserved key -`(event_date, path, status, method)`. Rollout step 4 verifies whether the reserved -datasource was ever deployed to the remote workspace; if it was, this schema ships as -a versioned replacement datasource with a cutover, not an in-place edit. +Typed sources only: `env` comes from settings state (production configs may set no +header), `template_cache_state` from the typed response extension rather than the +`x-ts-template-cache` header (operator-configured response headers can override +managed headers), `service_id` and `pop` from the Fastly environment. `cache_state` +from the reserved schema is dropped: the guest cannot observe the fronting cache, and +guest-visible cache behavior is already carried by `template_cache_state` and +`origin_ms`. Rows exist only for guest-handled requests; fronting-cache hits are +invisible by construction and the dashboard documentation says so. + +Sorting key: `(event_date, service_id, publisher_domain, env, route_class, pop, +status)`. Grafana time filtering uses `$__timeFilter(event_ts)` and every panel query +also carries an `event_date` predicate so the primary index prunes; rollout validates +the panel queries with `EXPLAIN` before the dashboard is committed. This replaces the +reserved key `(event_date, path, status, method)`. Rollout step 4 verifies whether the +reserved datasource was ever deployed to the remote workspace; if it was, this schema +ships as a versioned replacement datasource with a cutover, not an in-place edit. ## 10. Emission mechanics -- Point: Fastly `main.rs`, strictly after `send_edgezero_response` returns (the body - has fully streamed). The row can never affect TTFB or block delivery. -- Sampling: uniform per-request decision against `tinybird.access_sample_rate` - (validation `0.0..=1.0` already exists). No client stickiness. Sampled-out requests - are silent; every other drop (row build failure, send failure, non-2xx) logs a - warning naming the reason, so lost diagnostic rows are visible. +- `AccessTelemetrySnapshot`: built unconditionally at the freeze point, before + `into_parts()` consumes the response. It captures method, status, route metadata + (`route_class`, `route_template`), typed dimension states (`env`, + `template_cache_state`, geo country), and the transport context needed to emit + (backend spec, secret store name, dataset, token secret). It exists because nothing + else survives to post-send on every path: the request is consumed by dispatch, the + response by `into_parts()`, and `EcFinalizeState` is absent on asset, admin, and + error paths. +- `send_edgezero_response` returns the delivery outcome (bytes written and + success/partial/error) instead of `()`; the outcome feeds `resp_bytes` and lets a + partial delivery be recorded rather than silently averaged in. +- Ordering after the body-stream drive returns: snapshot `request_elapsed_ms` first, + run the existing pull-sync dispatch unchanged, then telemetry emission last, so + pull-sync is never delayed behind the ingest await and never included in + `request_elapsed_ms`. +- Sampling: uniform per-request decision against `tinybird.access_sample_rate`. No + client stickiness. Sampled-out requests are silent; every other drop (row build + failure, send failure, non-2xx) logs one warning naming the reason. There is no + cross-request warning suppression (per-request isolates hold no shared state); the + overload controls are the 2 s bounded await, the single-warning-per-request cap, and + `access_sample_rate` pushed down by config as the operational abort lever. Ingest + health is monitored from the Tinybird side via ingestion freshness on the + datasource, which catches quarantine and schema rejection that per-request warnings + cannot. - Transport: one NDJSON row to the Tinybird Events API: same `api_host`, reserved `access_dataset` and `access_token_secret`, 2 s first-byte and between-bytes timeouts, `max_body_bytes` guard, no retry. @@ -268,20 +358,19 @@ a versioned replacement datasource with a cutover, not an in-place edit. the pending response (it runs before delivery completes and cannot afford to wait), the access emitter runs after the client has the full response and therefore awaits the bounded ingest response and validates 2xx. A non-2xx or timeout logs a warning - with the status. This is what makes the warning semantics real rather than - aspirational. + with the status. - Budget: at `access_sample_rate = 1.0` this adds one backend request per request to - the service, after delivery. The sample rate is the budget control; 1.0 is a - diagnosis setting, not a steady state. -- Settings: the guard that rejects `tinybird.access_enabled = true` "until an emitter - is wired" flips into a wiring test in the same change. `access_enabled = true` - requires `tinybird.enabled` and a non-empty `api_host`. + the service, after delivery; during a Tinybird outage each such request holds its + sandbox for up to the bounded timeout. The sample rate is the budget control; 1.0 is + a diagnosis setting, not a steady state, and rollout treats sustained emission + warnings as the signal to dial it down. - Axum adapter: emits the header only; no Tinybird rows in v1. ## 11. Dashboard and query model No endpoint pipe in v1. Grafana queries `access_logs_raw` directly through the -ClickHouse connector with `$__timeFilter(event_ts)`, matching the auction dashboards. +ClickHouse connector with `$__timeFilter(event_ts)` plus an `event_date` predicate, +matching the auction dashboards. Dashboard: a new standalone `grafana/dashboards/edge-performance.json` in the telemetry repo (`trusted-server-tinybird`), performance only, no panels shared with @@ -289,8 +378,9 @@ the revenue and auction dashboards. Panels: - Phase percentiles (p50/p95/p99) by `route_class`, per phase column. - Stacked phase breakdown over time using the non-overlapping set: `appbuild_ms`, - `filter_ms`, `geo_ms`, `kv_ms`, `origin_ms`, `template_cache_ms`, and derived - `unattributed_ms`. `auction_wait_ms` and derived `stream_other_ms` chart in a + `filter_ms`, `geo_ms`, `kv_ms`, `origin_ms`, `template_cache_ms`, pre-header + auction wait (where `auction_wait_placement = 'pre_header'`), and derived + `unattributed_ms`. In-stream auction wait and derived `stream_other_ms` chart in a separate body-phase panel and never stack with pre-header phases. - PoP split, `ts_version` overlay, template-cache state rates. - Stall panel: rows with `request_elapsed_ms > 500` (post-body total, so body-only @@ -298,10 +388,15 @@ the revenue and auction dashboards. Panels: phase so the panel cannot confidently blame a small measured span while most time is uninstrumented. +All derivations use the `coalesce`/`greatest` forms from section 6; query tests cover +sparse phase combinations and both `auction_wait_placement` modes. + Sampling semantics for every aggregate: `sample_rate` must be operationally stable -within any queried window. Panels either filter to a single `sample_rate` value or -apply inverse-probability weights (`count() * 1/sample_rate`) for volume panels; -pooled unweighted quantiles across a rate change are documented as invalid. +within any queried window. Quantile panels filter strictly to a single `sample_rate` +value. Volume panels weight each row by `1.0 / sample_rate` (the inverse-probability +estimator is `sum(1.0 / sample_rate)` over emitted rows; `count() / rate` is valid +only when the query is already filtered to one rate). Pooled unweighted quantiles +across a rate change are documented as invalid. ## 12. Config surface @@ -315,11 +410,25 @@ New `ObservabilitySettings` struct with the single boolean, default off, standar environment override (`TRUSTED_SERVER__OBSERVABILITY__SERVER_TIMING_ENABLED`). Collection has no flag: the flags gate the two emission surfaces independently. +Tinybird flag structure: `tinybird.enabled` today arms the auction sink by itself, so +"enable Tinybird for access telemetry" would silently enable auction emission too. The +master flag is demoted to transport-only (host, store, credentials), and each emitter +gets its own switch: a new `tinybird.auction_enabled` defaulting to `true` (preserving +current behavior for existing configs) and the reserved `tinybird.access_enabled` +defaulting to `false`. A settings test locks the decoupling in both directions. + +Validation when `access_enabled = true`: `tinybird.enabled`, non-empty `api_host`, +non-empty `secret_store`, `access_dataset`, and `access_token_secret`, a positive +`max_body_bytes`, and `access_sample_rate > 0`. An armed-but-silent configuration +(`access_enabled = true`, `access_sample_rate = 0`) is a configuration error, not a +valid state; disabling is done with the flag, not the rate. + Rollback and compatibility, because `Settings` is `deny_unknown_fields`: - Deployment order is binary first, config second. Rollback order is config first - (remove the `[observability]` table), binary second. A config containing the table - must never be pushed while a pre-observability binary can still run. + (remove the `[observability]` table and any new tinybird keys), binary second. A + config containing the new fields must never be pushed while a pre-observability + binary can still run. - Config serialization omits the table when it equals the default, so round-tripping a config through tooling does not inject a field an older binary rejects. A compatibility test asserts the serialized default config parses under the previous @@ -328,44 +437,51 @@ Rollback and compatibility, because `Settings` is `deny_unknown_fields`: present-but-false in the base operator TOML (the same pattern the GPT integration documents in `trusted-server.example.toml`) and is flipped by config push. -`[tinybird]` gains no new keys; `access_enabled` and `access_sample_rate` are already -reserved. - ## 13. Error handling - Recording is infallible: saturating math, lock-failure drops the sample, no panics. - Header rendering failure (defensive `HeaderValue::from_str` error) logs and skips the header. -- Row emission failure logs a warning naming the reason and drops the row. The +- Row emission failure logs one warning naming the reason and drops the row. The response has already been delivered; there is nothing to degrade. ## 14. Testing - Core unit tests: phase accumulation, saturating math, `mark_headers_ready()` idempotence and both-surface consistency, render format (one decimal, omission of - unrecorded phases), row serialization shape. + unrecorded phases), row serialization shape, auction-wait placement recording. - Adapter tests (Fastly via Viceroy, Axum native): header present and well-formed on a - publisher route with the flag on; absent with the flag off; absent on a - shared-cacheable response (tsjs route) with the flag on; exactly one header across - all send paths; append preserves a pre-existing Server-Timing value; `ts-kv` - captures EC finalize work (proving the freeze point sits after it). + conclusively-private publisher route with the flag on; absent with the flag off; + absent on the shared-cacheable tsjs route and on a bare `max-age` response with the + flag on; exactly one TS-owned metric set (a single `ts-total`) with every + pre-existing Server-Timing value preserved, across all send paths; `ts-kv` captures + EC finalize work (proving the freeze point sits after it). +- Body-mode tests: ordinary streaming (in-stream wait nested in `stream_ms`), + Fastly shared-template authorized miss (buffered, pre-header wait), and Axum + (always buffered), each asserting placement and non-negative derivations. - Geo dedupe: finalize consumes `Resolved`; no retry on `Attempted(None)`; live - lookup only on `NotAttempted`; 401 skip preserved. -- Route template: serialization test proving a literal EC identifier never appears in - a row for the admin EC route; publisher fallback paths normalize to bounded output. -- Settings: `access_enabled` validation matrix; the former rejection test becomes the - wiring test; the serialized-default-config compatibility test against the previous - schema. + lookup only on `NotAttempted`; fallback lookups timed into `ts-geo`; asset-fallback + path carries `GeoLookupState` without `EcFinalizeState`; 401 skip preserved. +- Route template: adversarial normalization tests (literal EC identifier on the admin + route, email address in a segment, search-term segments, overlong segments) all + producing bounded content-free templates. +- Settings: the access validation matrix including the armed-but-silent rejection; + auction/access flag decoupling in both directions; the former rejection test becomes + the wiring test; the serialized-default-config compatibility test against the + previous schema. - Sink tests: `RecordingHttpClient` pattern; assert URI, NDJSON body shape, token - header, 2xx validation and warning on non-2xx, skip when sampled out. + header, 2xx validation and warning on non-2xx, skip when sampled out, ordering after + pull-sync. +- Query tests: derivation formulas against sparse rows and both placements. ## 15. Rollout and verification 1. Land collection + freeze point + header emission behind the flag, off everywhere. Full CI gate. -2. Staging deploy with the flag on. Then the delivery-layer check, verified with a - single request through the production route: the fronting VCL layer must pass the - appended Server-Timing through rather than overwrite it. Fallback if it clobbers: a +2. Staging deploy with the flag on. Delivery-layer verification is two-sided: a + pass-through request confirming the appended Server-Timing survives the fronting + VCL, and a MISS-then-HIT replay against a cacheable route confirming no stale + timing header is ever served from cache. Fallback if the VCL clobbers the header: a one-line VCL change on the delivery service, or mirroring the value to `x-ts-timing` while that lands. 3. Production flag on. Confirm @@ -374,33 +490,35 @@ reserved. actually collects; the publisher monitoring extension renders it only after a small change on their side. 4. Verify whether `access_logs_raw` exists in the remote Tinybird workspace. If yes, - ship the schema as a versioned replacement with cutover; if no, edit in place. Then - land the row schema, sink, and settings unwiring; sample at 1.0 during stall - diagnosis; then the dashboard. + ship the schema as a versioned replacement with cutover; if no, edit in place. + Validate the dashboard panel queries with `EXPLAIN` against the sorting key. Then + land the row schema, sink, and settings changes; sample at 1.0 during stall + diagnosis with ingestion-freshness monitoring on the datasource; then the + dashboard. 5. Success criterion: the next stall window is attributable from one response header or one dashboard query, with no live probing session. ## 16. Overhead -Roughly ten monotonic clock reads, one stored snapshot, and one ~130-byte header per +Roughly ten monotonic clock reads, two stored snapshots, and one ~130-byte header per request; one sampled HTTP POST with a bounded await after the response has fully -streamed. No allocation in the hot path beyond the one `Arc` at entry and the rendered -header string at the freeze point. +streamed. No allocation in the hot path beyond the one `Arc` at entry, the +`AccessTelemetrySnapshot` at the freeze point, and the rendered header string. ## 17. Decisions and open questions - **Public exposure is a decision, not an open question.** The header is all-traffic when enabled. Rationale: values are durations only; the delivery layer already exposes `hit-state` and `time-elapsed` publicly on every response; filter vendor - identity is masked; shared-cacheable responses are excluded from emission so a cache - cannot replay stale timings. Revisit (quantization or gating) only if a concrete + identity is masked; emission is restricted to conclusively-private responses so no + cache can replay stale timings. Revisit (quantization or gating) only if a concrete abuse surfaces. - The fronting delivery layer's Server-Timing pass-through is unverified until the first staging deploy (step 2). This is the only known external dependency. - Body-phase capture threads the timings handle into the streaming closure in `publisher.rs`; the exact seam is an implementation-plan detail, with the constraint that a dropped handle (error paths, early client disconnect) must still yield a - valid row with null body-phase fields. + valid row with null body-phase fields and a recorded delivery outcome. - The stall window itself remains unattributed until this ships. If it recurs first, the bisection runbook from 2026-08-21 (cookie-free curl UA request, static-asset path versus HTML path) is the fallback. From fb4f51284838b31026dfbef7c365956fadf7d33c Mon Sep 17 00:00:00 2001 From: Jason Evans Date: Mon, 24 Aug 2026 13:35:41 -0500 Subject: [PATCH 4/5] Add request phase timing implementation plan --- .../plans/2026-08-24-request-phase-timing.md | 1009 +++++++++++++++++ 1 file changed, 1009 insertions(+) create mode 100644 docs/superpowers/plans/2026-08-24-request-phase-timing.md diff --git a/docs/superpowers/plans/2026-08-24-request-phase-timing.md b/docs/superpowers/plans/2026-08-24-request-phase-timing.md new file mode 100644 index 000000000..f6db83d83 --- /dev/null +++ b/docs/superpowers/plans/2026-08-24-request-phase-timing.md @@ -0,0 +1,1009 @@ +# Request Phase Timing Implementation Plan + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** Every application response attributes its own server time by phase via a +Server-Timing header and a sampled Tinybird access-telemetry row. + +**Architecture:** A core `RequestTimings` handle (Arc-shared, infallible recording) +collects phase spans always-on; the Fastly adapter freezes and emits at +`send_edgezero_response` immediately before `into_parts()`; a post-send emitter ships +one NDJSON row to the Tinybird Events API with a bounded, 2xx-validated await. + +**Tech Stack:** Rust 2024, `edgezero` HTTP types, Fastly Compute (wasm32-wasip1, +Viceroy tests), Axum (native tests), Tinybird Events API. + +**Spec:** `docs/superpowers/specs/2026-08-24-request-phase-timing-design.md`: the +plan argues from the spec; executors read both. Spec section numbers are cited per +task. + +## Global Constraints + +- Errors use `error-stack` (`Report`); errors defined with + `derive_more::Display`; never thiserror, never anyhow (except the Spin entry point). +- No `unwrap()` in production code; `expect("should ...")` only. Assertion messages + `"should ..."`. Tests use Arrange-Act-Assert. +- No inline comments; comments on their own line above the code. +- Functions never exceed 7 arguments; use a struct instead (this bit + `ec_finalize_response` in review; the timings handle travels inside existing state). +- No local imports inside functions; `use super::*` only in `#[cfg(test)]`. +- Only example/fictional data in tests and docs (`example.com` domains). +- Recording is infallible: saturating math, lock failure drops the sample, no panics + (spec 5, 13). +- Vendor identity never appears in emitted surfaces: the filter span is `ts-filter` + (spec 3). +- Test commands: `cargo test-axum` (native, fast inner loop), `cargo test-fastly` + (Viceroy) for adapter tasks. Before PR handoff: the full CI gate list in + `CLAUDE.md`. +- Commit style: sentence case, imperative, no prefixes, no trailers. + +## File Structure + +| File | Responsibility | +| ----------------------------------------------------------------- | -------------------------------------------------------------------------------------------------- | +| `crates/trusted-server-core/src/request_timing.rs` (new) | `Phase`, `AuctionWaitPlacement`, `RequestTimings`, `PhaseSpan`, `TimingSnapshot`, header rendering | +| `crates/trusted-server-core/src/access_telemetry.rs` (new) | `RouteClass`, `publisher_route_template`, `AccessTelemetrySnapshot`, `AccessEventRow` NDJSON | +| `crates/trusted-server-core/src/geo.rs` (modify) | `GeoLookupState` response-extension type | +| `crates/trusted-server-core/src/settings.rs` (modify) | `ObservabilitySettings`, tinybird flag decoupling, access validation | +| `crates/trusted-server-core/src/publisher.rs` (modify) | `ts-origin`, `ts-template-cache`, auction-wait spans | +| `crates/trusted-server-core/src/ec/kv.rs` (modify) | `ts-kv` at the graph abstraction | +| `crates/trusted-server-adapter-fastly/src/main.rs` (modify) | T0, appbuild span, freeze point, `DeliveryOutcome`, post-send emission ordering | +| `crates/trusted-server-adapter-fastly/src/app.rs` (modify) | filter span, geo span + `GeoLookupState` attach, route class assignment | +| `crates/trusted-server-adapter-fastly/src/middleware.rs` (modify) | finalize consumes `GeoLookupState` | +| `crates/trusted-server-adapter-fastly/src/tinybird.rs` (modify) | access sink with confirmed delivery | +| `crates/trusted-server-adapter-axum/src/` (modify) | terminal freeze layer, header emission | +| `tinybird/datasources/access_logs_raw.datasource` (modify) | phase-column schema, non-null sorting key | +| `trusted-server.example.toml` (modify) | `[observability]`, tinybird keys | + +Out of scope for this plan: the Grafana dashboard JSON (separate telemetry repo, +spec 11) and Cloudflare/Spin emission wiring (spec non-goal). + +--- + +### Task 1: Core `RequestTimings` + +**Files:** + +- Create: `crates/trusted-server-core/src/request_timing.rs` +- Modify: `crates/trusted-server-core/src/lib.rs` (add `pub mod request_timing;`) +- Test: same file, `#[cfg(test)]` + +**Interfaces:** + +- Consumes: nothing (leaf module; `std::time`, `std::sync`). +- Produces (later tasks rely on these exact names): + - `pub enum Phase { AppBuild, Filter, Geo, EcKv, Origin, TemplateCacheLookup, AuctionWait, Stream }` + - `pub enum AuctionWaitPlacement { PreHeader, InStream }` + - `#[derive(Clone)] pub struct RequestTimings` with: + - `pub fn new() -> Self` + - `pub fn record(&self, phase: Phase, dur: Duration)` (saturating accumulate) + - `pub fn record_auction_wait(&self, placement: AuctionWaitPlacement, dur: Duration)` + - `pub fn span(&self, phase: Phase) -> PhaseSpan` (records on drop) + - `pub fn mark_headers_ready(&self)` (first call wins) + - `pub fn mark_request_elapsed(&self)` (first call wins) + - `pub fn set_resp_bytes(&self, bytes: u64)` + - `pub fn server_timing_value(&self) -> Option` + - `pub fn snapshot(&self) -> TimingSnapshot` + - `pub struct TimingSnapshot { pub time_elapsed_ms: Option, pub request_elapsed_ms: Option, pub appbuild_ms: Option, pub filter_ms: Option, pub geo_ms: Option, pub kv_ms: Option, pub origin_ms: Option, pub template_cache_ms: Option, pub auction_wait_ms: Option, pub stream_ms: Option, pub auction_wait_placement: Option, pub resp_bytes: Option }` + +- [ ] **Step 1: Write the failing tests** + +```rust +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn render_omits_unrecorded_phases_and_orders_total_first() { + let timings = RequestTimings::new(); + timings.record(Phase::Filter, Duration::from_micros(9_100)); + timings.mark_headers_ready(); + let value = timings + .server_timing_value() + .expect("should render after mark_headers_ready"); + assert!( + value.starts_with("ts-total;dur="), + "should lead with ts-total: {value}" + ); + assert!(value.contains("ts-filter;dur=9.1"), "should render one decimal: {value}"); + assert!(!value.contains("ts-geo"), "should omit unrecorded phases: {value}"); + } + + #[test] + fn render_returns_none_before_headers_ready() { + let timings = RequestTimings::new(); + timings.record(Phase::Geo, Duration::from_millis(1)); + assert!(timings.server_timing_value().is_none(), "should require the snapshot"); + } + + #[test] + fn repeated_phases_accumulate_saturating() { + let timings = RequestTimings::new(); + timings.record(Phase::Geo, Duration::from_millis(2)); + timings.record(Phase::Geo, Duration::from_millis(3)); + timings.mark_headers_ready(); + let snapshot = timings.snapshot(); + assert_eq!(snapshot.geo_ms, Some(5), "should accumulate repeats"); + } + + #[test] + fn mark_headers_ready_is_first_call_wins() { + let timings = RequestTimings::new(); + timings.mark_headers_ready(); + let first = timings.snapshot().time_elapsed_ms; + std::thread::sleep(Duration::from_millis(5)); + timings.mark_headers_ready(); + assert_eq!(timings.snapshot().time_elapsed_ms, first, "should not restamp"); + } + + #[test] + fn span_guard_records_on_drop() { + let timings = RequestTimings::new(); + { + let _span = timings.span(Phase::Origin); + std::thread::sleep(Duration::from_millis(2)); + } + timings.mark_headers_ready(); + assert!( + timings.snapshot().origin_ms.expect("should record on drop") >= 1, + "should measure elapsed span time" + ); + } + + #[test] + fn auction_wait_records_placement() { + let timings = RequestTimings::new(); + timings.record_auction_wait(AuctionWaitPlacement::PreHeader, Duration::from_millis(40)); + let snapshot = timings.snapshot(); + assert_eq!(snapshot.auction_wait_ms, Some(40), "should record wait"); + assert_eq!( + snapshot.auction_wait_placement, + Some(AuctionWaitPlacement::PreHeader), + "should record placement" + ); + } + + #[test] + fn rendered_names_never_include_vendor_terms() { + let timings = RequestTimings::new(); + for phase in [Phase::AppBuild, Phase::Filter, Phase::Geo, Phase::EcKv, Phase::Origin, Phase::TemplateCacheLookup] { + timings.record(phase, Duration::from_millis(1)); + } + timings.mark_headers_ready(); + let value = timings.server_timing_value().expect("should render"); + assert!(!value.to_ascii_lowercase().contains("datadome"), "should mask vendors"); + } +} +``` + +- [ ] **Step 2: Run to verify failure** + +Run: `cargo test-axum -p trusted-server-core request_timing` +Expected: compile FAIL, module does not exist. + +- [ ] **Step 3: Implement** + +```rust +//! Per-request phase timing collection and Server-Timing rendering. +//! +//! Collection is always-on and infallible: saturating math, lock failure +//! drops the sample, no panics. See the design spec +//! `docs/superpowers/specs/2026-08-24-request-phase-timing-design.md`. + +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; + +const PHASE_COUNT: usize = 8; + +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum Phase { + AppBuild, + Filter, + Geo, + EcKv, + Origin, + TemplateCacheLookup, + AuctionWait, + Stream, +} + +impl Phase { + fn index(self) -> usize { /* match self -> 0..=7 */ } + + /// Header entry name; row-only phases return None. + fn header_name(self) -> Option<&'static str> { + match self { + Self::AppBuild => Some("ts-appbuild"), + Self::Filter => Some("ts-filter"), + Self::Geo => Some("ts-geo"), + Self::EcKv => Some("ts-kv"), + Self::Origin => Some("ts-origin"), + Self::TemplateCacheLookup => Some("ts-template-cache"), + Self::AuctionWait | Self::Stream => None, + } + } +} + +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum AuctionWaitPlacement { + PreHeader, + InStream, +} + +struct Inner { + t0: Instant, + phases: [Option; PHASE_COUNT], + headers_ready_total: Option, + request_elapsed: Option, + auction_wait_placement: Option, + resp_bytes: Option, +} + +#[derive(Clone)] +pub struct RequestTimings(Arc>); +``` + +Implementation notes (all bodies in this task, none deferred): + +- Every method takes `if let Ok(mut inner) = self.0.lock()` and silently returns on + poison, per the infallibility constraint. +- `record` accumulates with `saturating_add` semantics + (`Some(existing.saturating_add(dur))`). +- `mark_headers_ready` and `mark_request_elapsed` write `t0.elapsed()` only when the + slot is `None`. +- `server_timing_value` returns `None` unless `headers_ready_total` is set; renders + `ts-total` first from the stored snapshot, then the six header phases in enum order + with `{:.1}` millisecond formatting (`dur.as_secs_f64() * 1000.0`). +- `PhaseSpan { timings: RequestTimings, phase: Phase, started: Instant }`; `Drop` + calls `record(self.phase, self.started.elapsed())`. +- `TimingSnapshot` converts each `Duration` with + `u32::try_from(dur.as_millis()).unwrap_or(u32::MAX)`. +- `impl Default for RequestTimings` delegates to `new()`. + +- [ ] **Step 4: Run to verify pass** + +Run: `cargo test-axum -p trusted-server-core request_timing` +Expected: all 7 tests PASS. + +- [ ] **Step 5: Commit** + +```bash +git add crates/trusted-server-core/src/request_timing.rs crates/trusted-server-core/src/lib.rs +git commit -m "Add RequestTimings phase collection and Server-Timing rendering" +``` + +--- + +### Task 2: Settings: `[observability]`, tinybird decoupling, access validation + +**Files:** + +- Modify: `crates/trusted-server-core/src/settings.rs` +- Modify: `trusted-server.example.toml` + +**Interfaces:** + +- Produces: + - `pub struct ObservabilitySettings { pub server_timing_enabled: bool }` as + `settings.observability`, `#[serde(default)]` on the field and + `#[serde(skip_serializing_if = "ObservabilitySettings::is_default")]`. + - `TinybirdSettings.auction_enabled: bool` (`#[serde(default = "default_true")]`). + - `prepare_runtime` validation: `access_enabled` requires `enabled`, non-empty + `api_host`, `secret_store`, `access_dataset`, `access_token_secret`, + `max_body_bytes > 0`, and `access_sample_rate > 0.0`. + +- [ ] **Step 1: Write the failing tests** (in `settings.rs` tests module) + +```rust +#[test] +fn observability_defaults_off_and_serializes_away() { + let settings = create_test_settings(); + assert!(!settings.observability.server_timing_enabled, "should default off"); + let toml = toml::to_string(&settings).expect("should serialize settings"); + assert!( + !toml.contains("[observability]"), + "should omit the default table so a prior binary can parse the config" + ); +} + +#[test] +fn access_enabled_requires_positive_sample_rate() { + // access_enabled = true with access_sample_rate = 0 is armed-but-silent: an error. + let err = settings_from_toml_with( + "[tinybird]\nenabled = true\napi_host = \"api.example.com\"\naccess_enabled = true\naccess_sample_rate = 0.0\n", + ) + .expect_err("should reject armed-but-silent access telemetry"); + assert!(format!("{err:?}").contains("access_sample_rate"), "should name the field"); +} + +#[test] +fn access_and_auction_emission_are_independent() { + let settings = settings_from_toml_with( + "[tinybird]\nenabled = true\napi_host = \"api.example.com\"\nauction_enabled = false\naccess_enabled = true\naccess_sample_rate = 1.0\n", + ) + .expect("should accept access without auction"); + assert!(!settings.tinybird.auction_enabled, "should disable auction emission"); + assert!(settings.tinybird.access_enabled, "should enable access emission"); +} + +#[test] +fn auction_enabled_defaults_true_for_existing_configs() { + let settings = settings_from_toml_with("[tinybird]\nenabled = true\napi_host = \"api.example.com\"\n") + .expect("should parse a pre-decoupling config"); + assert!(settings.tinybird.auction_enabled, "should preserve current behavior"); +} +``` + +Also REPLACE the existing rejection test +(`tinybird_access_enabled_is_rejected_until_emitter_is_wired`, `settings.rs:4123`) +with a wiring test asserting a fully-specified access config is accepted. + +- [ ] **Step 2: Run to verify failure** + +Run: `cargo test-axum -p trusted-server-core observability access_enabled auction_enabled` +Expected: compile FAIL (`observability` field missing). + +- [ ] **Step 3: Implement** + +- Add `ObservabilitySettings` (derive `Debug, Clone, Default, PartialEq, Deserialize, +Serialize`, `#[serde(deny_unknown_fields)]`), with + `fn is_default(&self) -> bool { *self == Self::default() }`. +- Add the `observability` field to `Settings` with the serde attributes above. +- Add `auction_enabled` to `TinybirdSettings` with `default_true()`; update + `Default for TinybirdSettings`. +- Extend `TinybirdSettings::prepare_runtime` with the access validation matrix; error + messages name the failing field (`"tinybird.access_sample_rate must be > 0 when +access_enabled"` and so on). +- `trusted-server.example.toml`: add a commented `[observability]` block with + `server_timing_enabled = false` present-but-false and the env-override note (the + overlay cannot create a missing leaf), plus `auction_enabled`/access keys in the + tinybird section comments. +- Gate the auction sink: in `crates/trusted-server-adapter-fastly/src/app.rs`, + `auction_sink_from_settings` condition becomes + `settings.tinybird.enabled && settings.tinybird.auction_enabled`. + +- [ ] **Step 4: Run to verify pass** + +Run: `cargo test-axum -p trusted-server-core` then `cargo test-fastly` (the sink gate +touches the Fastly adapter). +Expected: PASS, including the replaced wiring test. + +- [ ] **Step 5: Commit** + +```bash +git add crates/trusted-server-core/src/settings.rs trusted-server.example.toml crates/trusted-server-adapter-fastly/src/tinybird.rs crates/trusted-server-adapter-fastly/src/app.rs +git commit -m "Add observability settings and decouple tinybird access and auction emission" +``` + +--- + +### Task 3: Fastly freeze point, header emission, `DeliveryOutcome` + +**Files:** + +- Modify: `crates/trusted-server-adapter-fastly/src/main.rs` (entry T0, appbuild span, + `send_edgezero_response`) +- Test: `crates/trusted-server-adapter-fastly/src/app.rs` tests module (route-level + tests run under Viceroy) + +**Interfaces:** + +- Consumes: `RequestTimings`, `Phase` (Task 1); + `trusted_server_core::cache_policy::cache_control_headers_are_private_or_no_store`. +- Produces: + - `RequestTimings` inserted into request extensions at dispatch + (`core_req.extensions_mut().insert(timings.clone())`), alongside the existing + `config_store`/`device_signals`/`client_info` inserts. + - `send_edgezero_response(response, effects, timings) -> DeliveryOutcome` where + `pub(crate) struct DeliveryOutcome { pub bytes: u64, pub result: DeliveryResult }` + and `pub(crate) enum DeliveryResult { Complete, Error }` (streaming partial + detection lands in Task 6). + +- [ ] **Step 1: Write the failing tests** + +```rust +#[test] +fn server_timing_emitted_on_private_response_when_enabled() { + // Arrange: settings with observability.server_timing_enabled = true; publisher + // route fixture whose response is Cache-Control: private, no-store. + // Act: dispatch through the full adapter path. + // Assert: + let header = response_header(&response, "server-timing").expect("should emit header"); + assert!(header.contains("ts-total;dur="), "should carry the stored total"); + assert_eq!( + header.matches("ts-total").count(), 1, + "should emit exactly one TS-owned metric set" + ); +} + +#[test] +fn server_timing_absent_when_flag_off() { /* same fixture, flag false: no ts-total */ } + +#[test] +fn server_timing_absent_on_cacheable_responses() { + // tsjs route (public, max-age=31536000, immutable) and a bare max-age=60 response: + // both must carry no ts-total even with the flag on. +} + +#[test] +fn preexisting_server_timing_values_survive() { + // Fixture response already carrying Server-Timing: upstream;dur=1 stays present + // alongside the appended TS set. +} +``` + +- [ ] **Step 2: Run to verify failure** + +Run: `cargo test-fastly server_timing` +Expected: FAIL, no header emitted. + +- [ ] **Step 3: Implement** + +In `edgezero_main` (`main.rs`): + +```rust +let timings = RequestTimings::new(); +{ + let _appbuild = timings.span(Phase::AppBuild); + // existing: open_trusted_server_config_store() + build_app_with_state() +} +``` + +Move the config-store open inside the span scope. Insert `timings.clone()` into +request extensions before dispatch. Thread the handle into both send sites and the +error paths by value (it is a cheap clone). + +In `send_edgezero_response`, immediately before `response.into_parts()`: + +```rust +timings.mark_headers_ready(); +let conclusively_private = + cache_control_headers_are_private_or_no_store(response.headers()); +if settings_enabled_server_timing && conclusively_private { + if let Some(value) = timings.server_timing_value() { + match HeaderValue::from_str(&value) { + Ok(header_value) => { + response.headers_mut().append(header::SERVER_TIMING, header_value); + } + Err(error) => log::warn!("skipping server-timing header: {error}"), + } + } +} +``` + +`settings_enabled_server_timing` arrives as a `bool` captured from the settings +snapshot at the call sites (the function already receives per-call context; extend its +parameters, staying at or under seven, or pass a small +`SendContext { timings: RequestTimings, server_timing_enabled: bool }`). Return +`DeliveryOutcome`; existing callers ignore it in this task (Task 8 consumes it). + +- [ ] **Step 4: Run to verify pass** + +Run: `cargo test-fastly` and `cargo clippy-fastly` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add crates/trusted-server-adapter-fastly/src/main.rs crates/trusted-server-adapter-fastly/src/app.rs +git commit -m "Emit Server-Timing at the send freeze point on conclusively private responses" +``` + +--- + +### Task 4: Filter span and geo span with `GeoLookupState` dedupe + +**Files:** + +- Modify: `crates/trusted-server-core/src/geo.rs` (add `GeoLookupState`) +- Modify: `crates/trusted-server-adapter-fastly/src/app.rs` + (`run_pre_route_filters` wrapper, `build_ec_request_state` geo span + state attach) +- Modify: `crates/trusted-server-adapter-fastly/src/middleware.rs` and `main.rs` + (`resolve_geo_for_response` consumes carried state) + +**Interfaces:** + +- Consumes: `RequestTimings` from request extensions (Task 3). +- Produces: + - `pub enum GeoLookupState { NotAttempted, Attempted, Resolved(GeoInfo) }` in + `trusted_server_core::geo`, attached as a response extension on every exit path + that attempted a lookup (including the asset fallback). + - `resolve_geo_for_response` gains the carried state as input: live lookup only on + `NotAttempted`; `Attempted` is never retried; fallback lookups are wrapped in + `timings.span(Phase::Geo)`. + +- [ ] **Step 1: Write the failing tests** + +```rust +#[test] +fn finalize_reuses_request_phase_geo_without_second_lookup() { + // Counting geo stub: dispatch a publisher route; assert lookup count == 1 and + // x-geo-country still set on the response. +} + +#[test] +fn failed_lookup_is_not_retried() { + // Stub returns None once; assert GeoLookupState::Attempted carried and the + // finalize path performs zero further lookups. +} + +#[test] +fn asset_fallback_carries_geo_state_without_ec_finalize_state() { + // Asset route: response extension holds GeoLookupState, EcFinalizeState absent. +} + +#[test] +fn filter_span_recorded_when_request_filter_runs() { + // Registry fixture with a test request filter; assert snapshot().filter_ms is Some. +} + +#[test] +fn geo_lookup_skipped_for_unauthorized_responses() { + // Existing 401 rule preserved: no lookup, state NotAttempted. +} +``` + +- [ ] **Step 2: Run to verify failure** + +Run: `cargo test-fastly geo_ filter_span` +Expected: FAIL (lookup count 2; no `GeoLookupState`). + +- [ ] **Step 3: Implement** + +- `GeoLookupState` derives `Debug, Clone`; store in response extensions from the + dispatch layer right after `build_ec_request_state` resolves (or fails) its lookup. +- Wrap the `build_ec_request_state` lookup and any finalize fallback lookup in + `timings.span(Phase::Geo)` (accumulating slot handles the repeat case). +- Wrap `run_pre_route_filters` (`app.rs:751`) in `timings.span(Phase::Filter)`, + recording only when at least one filter is registered (skip the span when the + registry has no request filters, so the header omits `ts-filter` on unconfigured + deployments). +- `resolve_geo_for_response(response, carried: &GeoLookupState, client_ip, lookup)` + keeps the 401 short-circuit first, then matches the carried state. + +- [ ] **Step 4: Run to verify pass** + +Run: `cargo test-fastly` and `cargo test-axum` +Expected: PASS including untouched existing geo header tests. + +- [ ] **Step 5: Commit** + +```bash +git add crates/trusted-server-core/src/geo.rs crates/trusted-server-adapter-fastly/src/app.rs crates/trusted-server-adapter-fastly/src/middleware.rs crates/trusted-server-adapter-fastly/src/main.rs +git commit -m "Record filter and geo spans and dedupe the per-request geo lookup" +``` + +--- + +### Task 5: Core spans: origin, template cache, KV abstraction + +**Files:** + +- Modify: `crates/trusted-server-core/src/publisher.rs` (origin send ~4496, template + cache lookup ~4391 on current main) +- Modify: `crates/trusted-server-core/src/ec/kv.rs` (graph-level `ts-kv`) +- Test: `publisher.rs` and `ec/kv.rs` test modules + +**Interfaces:** + +- Consumes: `RequestTimings` read from request extensions inside + `handle_publisher_request`; `KvIdentityGraph` gains + `pub fn with_timings(self, timings: RequestTimings) -> Self` (builder-style, + optional field), set where the graph is constructed in `main.rs`. +- Produces: `origin_ms`, `template_cache_ms`, `kv_ms` populated in snapshots. + +- [ ] **Step 1: Write the failing tests** + +```rust +#[test] +fn origin_span_covers_the_publisher_fetch() { + // Stubbed origin with a small injected delay; assert snapshot().origin_ms is Some. +} + +#[test] +fn template_cache_span_recorded_only_when_lookup_runs() { + // Inline mode fixture: template_cache_ms None. Shared-mode eligible fixture: + // template_cache_ms Some. +} + +#[test] +fn kv_span_accumulates_across_graph_operations() { + // Stub KV recording two operations through KvIdentityGraph; assert kv_ms Some and + // covers both (accumulated, not last-write). +} + +#[test] +fn ec_finalize_kv_lands_before_freeze() { + // Adapter-level (test-fastly): EC-enabled fixture with eids cookies; assert the + // emitted header contains ts-kv, proving the freeze point sits after finalize. +} +``` + +- [ ] **Step 2: Run to verify failure** + +Run: `cargo test-axum -p trusted-server-core origin_span template_cache_span kv_span` +Expected: FAIL. + +- [ ] **Step 3: Implement** + +- `handle_publisher_request` reads the handle: + `let timings = req.extensions().get::().cloned().unwrap_or_default();` + (a defaulted handle records into nothing that ever renders, keeping non-adapter + tests unchanged). +- Origin: `let origin_span = timings.span(Phase::Origin);` immediately before + `services.http_client().send(platform_request).await`; `drop(origin_span)` when the + response headers are available (directly after the `match` arm binds the response). +- Template cache: same guard pattern around + `services.template_cache().lookup_or_reserve(key).await`. +- KV: `KvIdentityGraph` stores `timings: Option`; each public + operation (`get`, `write_entry`, `create_or_revive`, `upsert_partner_ids`, + `write_withdrawal_tombstone`, batch accessors) wraps its store call in + `Phase::EcKv` spans when the handle is present. `ec_finalize_response` keeps seven + arguments: the handle rides inside the graph, which it already receives. + +- [ ] **Step 4: Run to verify pass** + +Run: `cargo test-axum` then `cargo test-fastly` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add crates/trusted-server-core/src/publisher.rs crates/trusted-server-core/src/ec/kv.rs crates/trusted-server-adapter-fastly/src/main.rs +git commit -m "Record origin, template cache, and KV phase spans in core" +``` + +--- + +### Task 6: Body-phase capture: stream, auction wait placement, bytes + +**Files:** + +- Modify: `crates/trusted-server-core/src/publisher.rs` (seam wait + buffered wait) +- Modify: `crates/trusted-server-adapter-fastly/src/main.rs` (stream drive timing, + `DeliveryOutcome.bytes`) +- Test: `publisher.rs` tests + adapter tests + +**Interfaces:** + +- Consumes: `record_auction_wait` (Task 1), `DeliveryOutcome` (Task 3). +- Produces: `stream_ms`, `auction_wait_ms` + placement, `resp_bytes`, + `mark_request_elapsed()` called by the adapter immediately after the stream drive + returns. + +- [ ] **Step 1: Write the failing tests** + +```rust +#[test] +fn streaming_seam_wait_records_in_stream_placement() { + // Streaming fixture with a delayed auction: placement InStream, and + // stream_ms >= auction_wait_ms. +} + +#[test] +fn buffered_template_miss_records_pre_header_placement() { + // Shared-template authorized miss (buffered finalizer): placement PreHeader; the + // wait is recorded even though headers had not committed. +} + +#[test] +fn delivery_outcome_reports_bytes_and_request_elapsed_set() { + // Adapter: after send, snapshot has resp_bytes Some(body_len) and + // request_elapsed_ms Some; request_elapsed excludes post-send emitter time by + // construction (asserted by ordering test in Task 8). +} +``` + +- [ ] **Step 2: Run to verify failure** + +Run: `cargo test-fastly seam_wait buffered_template delivery_outcome` +Expected: FAIL. + +- [ ] **Step 3: Implement** + +- Streaming path: around the `collect_stream_auction(...)` await inside the body + stream, measure with `Instant::now()` and call + `timings.record_auction_wait(AuctionWaitPlacement::InStream, waited)`. The handle + reaches the stream closure through `OwnedProcessResponseParams`/assembly params (it + is `Clone`; add a field). +- Buffered path (`buffer_publisher_response_async` and the shared-template miss + finalizer): same measurement with `AuctionWaitPlacement::PreHeader`. +- Adapter stream drive: wrap the `block_on(stream_asset_body(...))` region; record + `Phase::Stream` with the elapsed drive time, count bytes written into + `DeliveryOutcome.bytes`, call `timings.set_resp_bytes(bytes)` and + `timings.mark_request_elapsed()` immediately after the drive returns, before + anything else post-send. + +- [ ] **Step 4: Run to verify pass** + +Run: `cargo test-fastly` and `cargo test-axum` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add crates/trusted-server-core/src/publisher.rs crates/trusted-server-adapter-fastly/src/main.rs +git commit -m "Capture stream duration, auction wait placement, and response bytes" +``` + +--- + +### Task 7: `AccessTelemetrySnapshot`, route class, route template + +**Files:** + +- Create: `crates/trusted-server-core/src/access_telemetry.rs` +- Modify: `crates/trusted-server-core/src/lib.rs` +- Modify: `crates/trusted-server-adapter-fastly/src/app.rs` (route class at handler + selection), `main.rs` (snapshot build at freeze point) + +**Interfaces:** + +- Consumes: `TimingSnapshot` (Task 1), `GeoLookupState` (Task 4). +- Produces: + - `pub enum RouteClass { PublisherHtml, Tsjs, IntegrationProxy, Ec, AuctionApi, Other }` + with `pub fn as_str(&self) -> &'static str` (snake_case values from the spec). + - `pub fn publisher_route_template(path: &str) -> String`: `/` plus first segment + filtered to `[a-z0-9_-]`, truncated to 32 chars, plus `/*` when deeper; empty or + disallowed first segments render `/other/*`. + - `pub struct AccessTelemetrySnapshot { pub method: String, pub status: u16, pub route_class: RouteClass, pub route_template: String, pub publisher_domain: String, pub env: String, pub service_id: String, pub pop: String, pub ts_version: String, pub country: String, pub template_cache_state: String, pub body_mode: &'static str, pub sample_rate: f64 }` + - `pub fn access_event_row(snapshot: &AccessTelemetrySnapshot, timings: &TimingSnapshot, event_ts_epoch_ms: u64) -> String` (one NDJSON line). + +- [ ] **Step 1: Write the failing tests** (adversarial, per spec 9) + +```rust +#[test] +fn admin_ec_route_template_never_contains_the_identifier() { + // Named-route template comes from the route table: "/_ts/admin/ec/{id}". + // Assert a row built for that route never contains a 64-hex EC id fixture. +} + +#[test] +fn publisher_paths_normalize_to_coarse_templates() { + assert_eq!(publisher_route_template("/news/some-article-slug"), "/news/*"); + assert_eq!(publisher_route_template("/"), "/"); + assert_eq!( + publisher_route_template("/user@example.com/profile"), + "/other/*", + "should reject non-allowlisted characters" + ); + assert_eq!( + publisher_route_template(&format!("/{}", "a".repeat(500))), + format!("/{}", "a".repeat(32)), + "should bound segment length" + ); + assert_eq!(publisher_route_template("/search terms here"), "/other/*"); +} + +#[test] +fn row_serializes_nulls_for_missing_phases() { + // Sparse TimingSnapshot: absent phases serialize as JSON null, dimension fields + // never null (unknown sentinel). +} +``` + +- [ ] **Step 2: Run to verify failure** + +Run: `cargo test-axum -p trusted-server-core access_telemetry route_template` +Expected: compile FAIL. + +- [ ] **Step 3: Implement** + +Row serialization via `serde_json::json!` mapping spec section 9 column names exactly +(`time_elapsed_ms`, `appbuild_ms`, ..., `auction_wait_placement` as +`pre_header|in_stream|none`). `env`/`pop`/`service_id` read by the adapter from +settings state and Fastly env (`FASTLY_SERVICE_ID`, `FASTLY_POP`), defaulting +`"unknown"`. Route class assigned in the named-route table (add a `RouteClass` column +to `NAMED_ROUTES`) and `RouteClass::PublisherHtml`/`Tsjs` for the fallback and tsjs +handlers. The snapshot is built unconditionally in `send_edgezero_response` right +after `mark_headers_ready()` and returned to the caller inside `DeliveryOutcome` (add +field `pub snapshot: AccessTelemetrySnapshot`). + +- [ ] **Step 4: Run to verify pass** + +Run: `cargo test-axum` and `cargo test-fastly` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add crates/trusted-server-core/src/access_telemetry.rs crates/trusted-server-core/src/lib.rs crates/trusted-server-adapter-fastly/src/app.rs crates/trusted-server-adapter-fastly/src/main.rs +git commit -m "Add access telemetry snapshot, route classes, and coarse route templates" +``` + +--- + +### Task 8: Access sink with confirmed delivery + post-send ordering + +**Files:** + +- Modify: `crates/trusted-server-adapter-fastly/src/tinybird.rs` (access sink) +- Modify: `crates/trusted-server-adapter-fastly/src/main.rs` (post-send ordering) + +**Interfaces:** + +- Consumes: `AccessTelemetrySnapshot` + `access_event_row` (Task 7), settings flags + (Task 2), `DeliveryOutcome` (Tasks 3/6). +- Produces: `pub(crate) async fn emit_access_event(services: &RuntimeServices, target: &TinybirdEventsTarget, row: String) -> Result<(), Report>` , + sends via `http_client().send(...)` (the blocking variant, post-delivery), checks + `response.status().is_success()`, warns with status otherwise. + +- [ ] **Step 1: Write the failing tests** + +```rust +#[test] +fn access_emitter_posts_ndjson_and_validates_2xx() { + // RecordingHttpClient returning 202: assert URI is /v0/events?name=access_logs_raw, + // body is the row, Authorization bearer from the secret stub. +} + +#[test] +fn access_emitter_warns_and_drops_on_non_2xx() { + // RecordingHttpClient returning 422: emit returns Err naming the status; no retry + // request recorded (exactly one request seen). +} + +#[test] +fn sampled_out_requests_emit_nothing() { + // access_sample_rate stub decision false: RecordingHttpClient sees zero requests. +} + +#[test] +fn post_send_order_is_elapsed_then_pull_sync_then_telemetry() { + // Instrumented stubs record call order; assert request_elapsed snapshot precedes + // pull-sync dispatch which precedes the telemetry send. +} +``` + +- [ ] **Step 2: Run to verify failure** + +Run: `cargo test-fastly access_emitter post_send_order` +Expected: FAIL. + +- [ ] **Step 3: Implement** + +- Reuse `TinybirdEventsTarget` with a second constructor + `from_access_config(config: TinybirdSettings)` using `access_dataset` and + `access_token_secret`. +- Sampling decision: `fn sampled_in(rate: f64, entropy: u64) -> bool` where entropy is + derived from the event timestamp nanos XOR a per-request counter (no `rand` + dependency; document that uniformity is approximate and sufficient). +- `main.rs` post-send, in order: `timings.mark_request_elapsed()` (already placed in + Task 6), existing pull-sync dispatch unchanged, then when + `settings.tinybird.enabled && settings.tinybird.access_enabled` and sampled in: + build the row from `outcome.snapshot` + `timings.snapshot()`, call + `emit_access_event`, log one warning on `Err`. + +- [ ] **Step 4: Run to verify pass** + +Run: `cargo test-fastly` and `cargo clippy-fastly` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add crates/trusted-server-adapter-fastly/src/tinybird.rs crates/trusted-server-adapter-fastly/src/main.rs +git commit -m "Emit confirmed access telemetry rows after pull-sync post-send" +``` + +--- + +### Task 9: Tinybird datasource schema + +**Files:** + +- Modify: `tinybird/datasources/access_logs_raw.datasource` + +**Interfaces:** + +- Consumes: column names exactly as serialized by `access_event_row` (Task 7). +- Produces: the deployed schema contract for the dashboard (separate repo). + +- [ ] **Step 1: Rewrite the schema** per spec section 9: keep + `event_ts DateTime64(3)`, `method`, `status UInt16`, `time_elapsed_ms UInt32`, + `sample_rate Float64`, `event_date` + 30-day TTL; add the columns from spec 9 with + dimension columns non-nullable `LowCardinality(String)` and phase columns + `Nullable(UInt32)`; drop `path` and `cache_state`; set + `ENGINE_SORTING_KEY "event_date, service_id, publisher_domain, env, route_class, pop, status"`. + +- [ ] **Step 2: Validate** with the tinybird toolchain if available locally + (`tb check` / project tests under `tinybird/tests`); otherwise assert the file + parses by review and rely on rollout step 4's remote verification. Add a fixture row + in `tinybird/fixtures` matching `access_event_row` output. + +- [ ] **Step 3: Commit** + +```bash +git add tinybird/datasources/access_logs_raw.datasource tinybird/fixtures +git commit -m "Extend access_logs_raw with phase columns and a non-null sorting key" +``` + +--- + +### Task 10: Axum adapter emission + +**Files:** + +- Modify: `crates/trusted-server-adapter-axum/src/` (terminal layer at the response + serialization boundary; locate the equivalent of the Fastly send path) +- Test: axum adapter tests (`cargo test-axum`) + +**Interfaces:** + +- Consumes: `RequestTimings`, header emission helper. Extract the emission block from + Task 3 into a shared core helper so both adapters call one function: + `pub fn append_server_timing_if_private(response: &mut Response, timings: &RequestTimings, enabled: bool)` + in `request_timing.rs` (move the Fastly inline logic here and re-point Task 3's call + site). +- Produces: Axum responses carry the header under the same conservative predicate; + `ts-appbuild` absent by construction (state built at startup); router-generated + 404/405 covered by the terminal layer; `/health` excluded by route match. + +- [ ] **Step 1: Write the failing tests** + +```rust +#[test] +fn axum_emits_header_on_private_response() { /* flag on, private response: ts-total present, ts-appbuild absent */ } + +#[test] +fn axum_404_carries_header_when_private() { /* router-generated 404 passes through the terminal layer */ } + +#[test] +fn axum_health_is_excluded() { /* /health: no ts-total */ } +``` + +- [ ] **Step 2: Run to verify failure** + +Run: `cargo test-axum axum_emits axum_404 axum_health` +Expected: FAIL. + +- [ ] **Step 3: Implement** the terminal layer: create `RequestTimings::new()` per + request at the outermost service layer, insert into request extensions, and at the + layer's response side call `mark_headers_ready()` + + `append_server_timing_if_private(...)`, skipping the `/health` path. + +- [ ] **Step 4: Run to verify pass** + +Run: `cargo test-axum` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add crates/trusted-server-adapter-axum/src crates/trusted-server-core/src/request_timing.rs crates/trusted-server-adapter-fastly/src/main.rs +git commit -m "Emit Server-Timing from the Axum terminal layer with adapter-specific semantics" +``` + +--- + +### Task 11: Full gate, docs, and PR + +- [ ] **Step 1: Docs.** Add a short operator section to `docs/guide/configuration.md`: + the `[observability]` flag, the tinybird access keys, the deploy/rollback ordering + from spec section 12 (binary first, config second; config first on rollback), and + the conservative emission rule. Run `cd docs && npm run format`. + +- [ ] **Step 2: Full CI gate list** from `CLAUDE.md`: + `cargo fmt --all -- --check`; all six clippy aliases; `test-fastly`, `test-axum`, + `test-cloudflare`, `test-spin`; the integration-tests parity suite; JS build/test + and formats. Cloudflare/Spin compile the new core modules (collection only), which + is exactly what the non-goal requires. + +- [ ] **Step 3: Commit docs, push the branch, open the implementation PR** referencing + the spec PR #1069 and issue #1068, with the rollout section of the spec quoted as + the deployment checklist (staging pass-through + MISS/HIT replay before production + flag-on). + +--- + +## Self-Review + +- Spec coverage: sections 5 (Task 1), 12 (Task 2), 7 (Tasks 3, 10), 8/8a (Tasks 4, + 10), 6 (Tasks 4-6), 9 (Tasks 7, 9), 10 (Task 8), 13 (Tasks 1, 3, 8), 14 (test + steps throughout), 15 steps 1-4 (Task 11 + deployment checklist). Section 11 + (dashboard) is explicitly out of scope for this repo's plan. +- Type consistency: `RequestTimings`/`TimingSnapshot`/`RouteClass`/ + `AccessTelemetrySnapshot`/`DeliveryOutcome` names and signatures match across + Tasks 1, 3, 6, 7, 8, 10. +- Known intentional deferral: `DeliveryResult::Partial` detection is named in Task 3 + and wired when the stream drive reports bytes in Task 6; no other deferrals. From a845f007d587acfd5d8f13086239091f19ce4cb4 Mon Sep 17 00:00:00 2001 From: Jason Evans Date: Mon, 24 Aug 2026 14:20:52 -0500 Subject: [PATCH 5/5] 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 --- .../plans/2026-08-24-request-phase-timing.md | 97 ++++++++++++------- .../2026-08-24-request-phase-timing-design.md | 79 ++++++++++----- 2 files changed, 117 insertions(+), 59 deletions(-) diff --git a/docs/superpowers/plans/2026-08-24-request-phase-timing.md b/docs/superpowers/plans/2026-08-24-request-phase-timing.md index f6db83d83..9ff3905f4 100644 --- a/docs/superpowers/plans/2026-08-24-request-phase-timing.md +++ b/docs/superpowers/plans/2026-08-24-request-phase-timing.md @@ -245,8 +245,9 @@ pub struct RequestTimings(Arc>); Implementation notes (all bodies in this task, none deferred): -- Every method takes `if let Ok(mut inner) = self.0.lock()` and silently returns on - poison, per the infallibility constraint. +- Every method takes `if let Ok(mut inner) = self.0.try_lock()` and silently + returns otherwise: contention and poison both drop the sample instead of waiting, + per the infallibility constraint. - `record` accumulates with `saturating_add` semantics (`Some(existing.saturating_add(dur))`). - `mark_headers_ready` and `mark_request_elapsed` write `t0.elapsed()` only when the @@ -471,11 +472,13 @@ if settings_enabled_server_timing && conclusively_private { } ``` -`settings_enabled_server_timing` arrives as a `bool` captured from the settings -snapshot at the call sites (the function already receives per-call context; extend its -parameters, staying at or under seven, or pass a small -`SendContext { timings: RequestTimings, server_timing_enabled: bool }`). Return -`DeliveryOutcome`; existing callers ignore it in this task (Task 8 consumes it). +`settings_enabled_server_timing` arrives inside a small +`SendContext { timings: RequestTimings, server_timing_enabled: bool }` so the +function stays at or under seven parameters. Return `DeliveryOutcome` with per-mode +semantics: buffered bodies capture the byte count from the body length before +`send_to_client()` (which returns no delivery result) and report complete-on-return; +the streaming branch gains a counting writer in Task 6. Existing callers ignore the +outcome in this task (Task 8 consumes it). - [ ] **Step 4: Run to verify pass** @@ -608,8 +611,14 @@ fn template_cache_span_recorded_only_when_lookup_runs() { #[test] fn kv_span_accumulates_across_graph_operations() { - // Stub KV recording two operations through KvIdentityGraph; assert kv_ms Some and - // covers both (accumulated, not last-write). + // Stub KV recording two operations through a TimedKvStore-wrapped graph; assert + // kv_ms Some and covers both (accumulated, not last-write). +} + +#[test] +fn consent_store_reads_are_timed_and_pull_sync_is_not() { + // Consent read through the decorated RuntimeServices store: kv_ms Some. + // Pull-sync graph built from the untimed store: records nothing. } #[test] @@ -635,11 +644,15 @@ Expected: FAIL. response headers are available (directly after the `match` arm binds the response). - Template cache: same guard pattern around `services.template_cache().lookup_or_reserve(key).await`. -- KV: `KvIdentityGraph` stores `timings: Option`; each public - operation (`get`, `write_entry`, `create_or_revive`, `upsert_partner_ids`, - `write_withdrawal_tombstone`, batch accessors) wraps its store call in - `Phase::EcKv` spans when the handle is present. `ec_finalize_response` keeps seven - arguments: the handle rides inside the graph, which it already receives. +- KV: add `TimedKvStore` (new type in `crates/trusted-server-core/src/platform/`), + a decorator implementing `PlatformKvStore` that wraps `Arc` + plus a `RequestTimings` handle and records `Phase::EcKv` around every trait + method. Every request-path `KvIdentityGraph` construction site (request setup, + identify, admin lookup, batch sync, finalization) receives the timed store; + consent-store access through `RuntimeServices` uses the same decorator; pull-sync + constructs its graph from the untimed store explicitly (add a test asserting the + pull-sync store records nothing). `ec_finalize_response` keeps seven arguments: + the handle rides inside the store the graph already receives. - [ ] **Step 4: Run to verify pass** @@ -708,11 +721,13 @@ Expected: FAIL. is `Clone`; add a field). - Buffered path (`buffer_publisher_response_async` and the shared-template miss finalizer): same measurement with `AuctionWaitPlacement::PreHeader`. -- Adapter stream drive: wrap the `block_on(stream_asset_body(...))` region; record - `Phase::Stream` with the elapsed drive time, count bytes written into - `DeliveryOutcome.bytes`, call `timings.set_resp_bytes(bytes)` and +- Adapter stream drive: wrap the `block_on(stream_asset_body(...))` region with a + counting writer that tallies bytes and observes truncation/error, record + `Phase::Stream` with the elapsed drive time, populate `DeliveryOutcome` with + bytes and Complete/Partial/Error, call `timings.set_resp_bytes(bytes)` and `timings.mark_request_elapsed()` immediately after the drive returns, before - anything else post-send. + anything else post-send. Buffered responses keep the Task 3 complete-on-return + semantics; `body_mode` distinguishes the regimes in the row. - [ ] **Step 4: Run to verify pass** @@ -734,8 +749,10 @@ git commit -m "Capture stream duration, auction wait placement, and response byt - Create: `crates/trusted-server-core/src/access_telemetry.rs` - Modify: `crates/trusted-server-core/src/lib.rs` -- Modify: `crates/trusted-server-adapter-fastly/src/app.rs` (route class at handler - selection), `main.rs` (snapshot build at freeze point) +- Modify: `crates/trusted-server-adapter-fastly/src/app.rs` (RouteMetadata attach at + handler wrappers), `main.rs` (snapshot build at freeze point), + `crates/trusted-server-core/src/publisher.rs` (typed template-cache state + extension) **Interfaces:** @@ -791,13 +808,20 @@ Expected: compile FAIL. Row serialization via `serde_json::json!` mapping spec section 9 column names exactly (`time_elapsed_ms`, `appbuild_ms`, ..., `auction_wait_placement` as -`pre_header|in_stream|none`). `env`/`pop`/`service_id` read by the adapter from -settings state and Fastly env (`FASTLY_SERVICE_ID`, `FASTLY_POP`), defaulting -`"unknown"`. Route class assigned in the named-route table (add a `RouteClass` column -to `NAMED_ROUTES`) and `RouteClass::PublisherHtml`/`Tsjs` for the fallback and tsjs -handlers. The snapshot is built unconditionally in `send_edgezero_response` right -after `mark_headers_ready()` and returned to the caller inside `DeliveryOutcome` (add -field `pub snapshot: AccessTelemetrySnapshot`). +`pre_header|in_stream|none`). `pop`/`service_id` read from Fastly env +(`FASTLY_SERVICE_ID`, `FASTLY_POP`), defaulting `"unknown"`; `env` derived by the +adapter from `FASTLY_IS_STAGING` (the `x-ts-env` input), never from `Settings`. +Route identity travels as a typed `RouteMetadata` response extension +(`pub struct RouteMetadata { pub route_class: RouteClass, pub route_template: String }` +in `access_telemetry.rs`): each named-route handler wrapper attaches its matched +route-table pattern verbatim, and the fallback and tsjs handlers attach their class +plus the coarse template; the freeze point consumes the extension (no `RouteClass` +column in `NAMED_ROUTES`, no reconstruction from a handler enum). Also in this task: +make `TemplateCacheResponseState` a typed response extension in `publisher.rs`, set +at every point that writes `x-ts-template-cache` so header and extension cannot +drift; the row reads the extension. The snapshot is built unconditionally in +`send_edgezero_response` right after `mark_headers_ready()` and returned inside +`DeliveryOutcome` (add field `pub snapshot: AccessTelemetrySnapshot`). - [ ] **Step 4: Run to verify pass** @@ -824,9 +848,12 @@ git commit -m "Add access telemetry snapshot, route classes, and coarse route te - Consumes: `AccessTelemetrySnapshot` + `access_event_row` (Task 7), settings flags (Task 2), `DeliveryOutcome` (Tasks 3/6). -- Produces: `pub(crate) async fn emit_access_event(services: &RuntimeServices, target: &TinybirdEventsTarget, row: String) -> Result<(), Report>` , - sends via `http_client().send(...)` (the blocking variant, post-delivery), checks - `response.status().is_success()`, warns with status otherwise. +- Produces: `pub(crate) async fn emit_access_event(client: &FastlyPlatformHttpClient, target: &TinybirdEventsTarget, row: String) -> Result<(), Report>`, + sending via the adapter's stateless platform client (the blocking variant, + post-delivery), checking `response.status().is_success()`, warning with status + otherwise. The transport context is adapter-owned and route-independent (target + derived from settings once at entry), so asset, admin, and error responses emit + without `RuntimeServices` or `EcFinalizeState`. - [ ] **Step 1: Write the failing tests** @@ -957,10 +984,12 @@ fn axum_health_is_excluded() { /* /health: no ts-total */ } Run: `cargo test-axum axum_emits axum_404 axum_health` Expected: FAIL. -- [ ] **Step 3: Implement** the terminal layer: create `RequestTimings::new()` per - request at the outermost service layer, insert into request extensions, and at the - layer's response side call `mark_headers_ready()` + - `append_server_timing_if_private(...)`, skipping the `/health` path. +- [ ] **Step 3: Implement** an outer service wrapper around the `RouterService` + inside `AxumDevServer` (not router middleware, which router-generated 404/405 + responses bypass and which returns before body serialization): create + `RequestTimings::new()` per request in the wrapper, insert into request + extensions, and on the wrapper's response side call `mark_headers_ready()` + + `append_server_timing_if_private(...)`, skipping the `/health` path by match. - [ ] **Step 4: Run to verify pass** diff --git a/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md b/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md index 96bdb3617..06f27c1c2 100644 --- a/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md +++ b/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md @@ -125,8 +125,9 @@ New module `crates/trusted-server-core/src/request_timing.rs`. - Sharing: `RequestTimings` is a cheap-clone handle, `Arc>`. It crosses three boundaries: adapter entry to core handlers, the streaming body closure (records body-phase spans after the response object has been handed off), and the adapter's - post-send emission read. A poisoned or contended lock must never fail a request: all - recording methods are infallible and drop the sample on lock failure. + post-send emission read. Access is exclusively `try_lock()`: a contended or + poisoned lock drops the sample immediately rather than waiting, so recording can + never delay a request. - Recording API: `timings.record(Phase::Geo, dur)` and a scope guard `timings.span(Phase::Origin)` that records on drop. Guards use saturating duration math; a non-monotonic reading records zero rather than panicking. The auction-wait @@ -154,16 +155,24 @@ so no new clock abstraction is needed. Naming follows the completed template-cache terminology migration (`x-ts-template-cache` is the emitted header on `main`; `c2` naming is retired). -`ts-kv` is instrumented at the shared identity-graph/KV abstraction -(`KvIdentityGraph` and the platform KV store wrapper), not at individual call sites, so -new callers cannot silently escape the span. Included pre-send operations: EC +`ts-kv` is instrumented by a timing decorator implementing `PlatformKvStore` that +wraps the store handed to request-scoped consumers, because no single existing +abstraction covers the taxonomy: EC graph operations go through `KvIdentityGraph` +while consent persistence uses `PlatformKvStore` directly, and graphs are constructed +independently in request setup, identify, admin lookup, batch sync, and finalization. +Every request-path graph construction receives the timed store; pull-sync explicitly +constructs its graph from an untimed store. Consent-store reads pass through the same +decorator and are timed like any other store call. Included pre-send operations: EC generation `create_or_revive`, identify-path graph reads and evaluation, finalize-path `ingest_eid_cookies`/`upsert_partner_ids` and withdrawal tombstones, consent-store reads on consent routes, and batch-sync graph access when it runs before send. Explicitly excluded: pull-sync work, which runs strictly after `send_to_client` and is -invisible to both surfaces. The timings handle reaches `ec_finalize_response` through -an existing context or a parameter object; that function already has the repository -maximum of seven arguments and does not gain an eighth. +invisible to both surfaces. The decorator measures store-call latency only: no value +passing through it is read, parsed, or recorded, and the emitted surfaces carry no +consent or identity payloads. This feature therefore needs no consent gate; it is the +site measuring its own infrastructure, not processing user data. The timings handle +reaches `ec_finalize_response` inside the graph it already receives; that function +keeps the repository maximum of seven arguments and does not gain an eighth. Row-only fields: @@ -252,9 +261,11 @@ structurally and its emissions are defined accordingly rather than pretending pa - `body_mode` is always `buffered`: the Axum HTTP client buffers upstream bodies, so `stream_ms` measures buffered-body write-out and `auction_wait_placement` is always `pre_header`. -- The freeze point is an Axum-terminal middleware layer that runs after all response - mutation, covering router-generated 404/405 responses; Axum's `/health` sits inside - the middleware stack and is excluded explicitly by route match. +- The freeze point is an outer service wrapper around the `RouterService` inside + `AxumDevServer`, not router middleware: router-generated 404/405 responses bypass + router middleware, and middleware returns before Axum serializes the body. The + wrapper sees every response including router-generated ones; `/health` is excluded + by path match inside the wrapper. - Axum emits the header only; no Tinybird rows in v1 (unchanged). Cloudflare and Spin: collection compiles, no emission wiring in v1 (unchanged). @@ -287,7 +298,7 @@ ClickHouse sorting keys cannot contain nullable columns): ``` `service_id` LowCardinality(String), -- FASTLY_SERVICE_ID; immutable deployment identity `publisher_domain` LowCardinality(String), -- matches auction schema -`env` LowCardinality(String), -- from typed settings state, never from a response header +`env` LowCardinality(String), -- adapter-derived: production | staging | unknown `route_class` LowCardinality(String), -- publisher_html | tsjs | integration_proxy | ec | auction_api | other `route_template` String, -- bounded, normalized; replaces path `body_mode` LowCardinality(String), -- streamed | buffered @@ -308,10 +319,21 @@ ClickHouse sorting keys cannot contain nullable columns): `pop` LowCardinality(String) -- FASTLY_POP, 'unknown' when absent ``` -Typed sources only: `env` comes from settings state (production configs may set no -header), `template_cache_state` from the typed response extension rather than the -`x-ts-template-cache` header (operator-configured response headers can override -managed headers), `service_id` and `pop` from the Fastly environment. `cache_state` +The matched route pattern does not survive dispatch today, so a typed +`RouteMetadata` response extension carries `route_class` and `route_template`: each +named-route handler wrapper attaches its route-table pattern verbatim (handlers +serving multiple patterns attach the one that matched), and the fallback and tsjs +handlers attach their class plus the coarse template. The freeze point consumes the +extension; nothing reconstructs routes from a handler enum or path regex. + +Typed sources only: `env` is adapter-owned, derived from the same Fastly +`FASTLY_IS_STAGING` input that drives `x-ts-env` (`Settings` has no environment +field and does not gain one). `template_cache_state` comes from a typed response +extension, not the `x-ts-template-cache` header (operator-configured response +headers can override managed headers): the currently private +`TemplateCacheResponseState` in `publisher.rs` becomes a typed response extension, +and every state transition sets the managed header and the extension together so +the two can never drift. `service_id` and `pop` come from the Fastly environment. `cache_state` from the reserved schema is dropped: the guest cannot observe the fronting cache, and guest-visible cache behavior is already carried by `template_cache_state` and `origin_ms`. Rows exist only for guest-handled requests; fronting-cache hits are @@ -329,15 +351,22 @@ ships as a versioned replacement datasource with a cutover, not an in-place edit - `AccessTelemetrySnapshot`: built unconditionally at the freeze point, before `into_parts()` consumes the response. It captures method, status, route metadata - (`route_class`, `route_template`), typed dimension states (`env`, - `template_cache_state`, geo country), and the transport context needed to emit - (backend spec, secret store name, dataset, token secret). It exists because nothing - else survives to post-send on every path: the request is consumed by dispatch, the - response by `into_parts()`, and `EcFinalizeState` is absent on asset, admin, and - error paths. -- `send_edgezero_response` returns the delivery outcome (bytes written and - success/partial/error) instead of `()`; the outcome feeds `resp_bytes` and lets a - partial delivery be recorded rather than silently averaged in. + (from the `RouteMetadata` extension), and typed dimension states (`env`, + `template_cache_state`, geo country). It exists because nothing else survives to + post-send on every path: the request is consumed by dispatch, the response by + `into_parts()`, and `EcFinalizeState` is absent on asset, admin, and error paths. +- The emitter's transport context is adapter-owned and route-independent: the + Events API target (backend spec, secret store name, dataset, token secret, sample + rate) derives from settings once at entry in `main.rs`, and the HTTP client is the + adapter's stateless platform client. Asset, admin, and error responses therefore + emit without `RuntimeServices` or `EcFinalizeState`. +- `send_edgezero_response` returns a delivery outcome instead of `()`, with + per-mode semantics because the two body paths observe different things. Streamed + bodies: a counting writer reports bytes written and distinguishes complete, + partial (truncated), and error outcomes. Buffered bodies: `send_to_client()` + returns no delivery result, so the byte count is captured from the body length + before the send and the outcome is complete-on-return with no partial detection; + `body_mode` in the row keeps the two regimes distinguishable in analysis. - Ordering after the body-stream drive returns: snapshot `request_elapsed_ms` first, run the existing pull-sync dispatch unchanged, then telemetry emission last, so pull-sync is never delayed behind the ingest await and never included in