diff --git a/crates/trusted-server-adapter-axum/Cargo.toml b/crates/trusted-server-adapter-axum/Cargo.toml index 15b6ee59d..09e8c77d2 100644 --- a/crates/trusted-server-adapter-axum/Cargo.toml +++ b/crates/trusted-server-adapter-axum/Cargo.toml @@ -20,6 +20,7 @@ path = "src/main.rs" [dependencies] async-trait = { workspace = true } +axum = { workspace = true } edgezero-adapter-axum = { workspace = true, features = ["axum"] } edgezero-core = { workspace = true } error-stack = { workspace = true } @@ -27,12 +28,11 @@ futures = { workspace = true } log = { workspace = true } reqwest = { workspace = true } simple_logger = { workspace = true } -tokio = { workspace = true, features = ["rt-multi-thread", "macros", "sync", "time"] } +tokio = { workspace = true, features = ["rt-multi-thread", "macros", "net", "signal", "sync", "time"] } +tower = { workspace = true, features = ["util"] } trusted-server-core = { workspace = true } [dev-dependencies] -axum = { workspace = true } base64 = { workspace = true } temp-env = { workspace = true } tokio = { workspace = true, features = ["rt-multi-thread", "macros"] } -tower = { workspace = true, features = ["util"] } diff --git a/crates/trusted-server-adapter-axum/src/app.rs b/crates/trusted-server-adapter-axum/src/app.rs index 4b71d07ce..4bdf27d01 100644 --- a/crates/trusted-server-adapter-axum/src/app.rs +++ b/crates/trusted-server-adapter-axum/src/app.rs @@ -565,15 +565,7 @@ impl Hooks for TrustedServerApp { } fn routes() -> RouterService { - let state = match build_state() { - Ok(s) => s, - Err(ref e) => { - log::error!("failed to build application state: {:?}", e); - return startup_error_router(e); - } - }; - - build_router(&state) + Self::routes_with_server_timing_flag().0 } } @@ -594,6 +586,28 @@ impl TrustedServerApp { let state = build_state_with_settings(settings)?; Ok(build_router(&state)) } + + /// Build the router alongside whether `Server-Timing` emission is + /// enabled, read from the same settings snapshot used to build the + /// router. + /// + /// The Axum dev server's terminal timing layer ([`crate::timing`]) needs + /// this flag once at startup: unlike the Fastly adapter, which rebuilds + /// `Settings` per request, the Axum dev server builds its application + /// state once and reuses the same [`RouterService`] for every request. + #[must_use] + pub fn routes_with_server_timing_flag() -> (RouterService, bool) { + let state = match build_state() { + Ok(s) => s, + Err(ref e) => { + log::error!("failed to build application state: {:?}", e); + return (startup_error_router(e), false); + } + }; + + let server_timing_enabled = state.settings.observability.server_timing_enabled; + (build_router(&state), server_timing_enabled) + } } fn build_router(state: &Arc) -> RouterService { diff --git a/crates/trusted-server-adapter-axum/src/lib.rs b/crates/trusted-server-adapter-axum/src/lib.rs index 2f15e566d..b1d4c3dd8 100644 --- a/crates/trusted-server-adapter-axum/src/lib.rs +++ b/crates/trusted-server-adapter-axum/src/lib.rs @@ -10,3 +10,6 @@ pub mod app; pub mod middleware; /// Platform-trait implementations backed by env vars and `reqwest`. pub mod platform; +/// Terminal timing layer wrapping the Axum dev server's tower `Service` +/// boundary with the request-phase `Server-Timing` freeze point. +pub mod timing; diff --git a/crates/trusted-server-adapter-axum/src/main.rs b/crates/trusted-server-adapter-axum/src/main.rs index 960982176..b8bc28ae2 100644 --- a/crates/trusted-server-adapter-axum/src/main.rs +++ b/crates/trusted-server-adapter-axum/src/main.rs @@ -1,6 +1,16 @@ -use edgezero_adapter_axum::dev_server::{AxumDevServer, AxumDevServerConfig}; -use edgezero_core::app::Hooks as _; +use std::net::SocketAddr; + +use axum::Router; +use edgezero_adapter_axum::dev_server::AxumDevServerConfig; +use edgezero_adapter_axum::service::EdgeZeroAxumService; +use edgezero_core::router::RouterService; +use tokio::net::TcpListener; +use tokio::runtime::Builder as RuntimeBuilder; +use tokio::signal; +use tower::Service as _; +use tower::service_fn; use trusted_server_adapter_axum::app::TrustedServerApp; +use trusted_server_adapter_axum::timing::TimingService; #[allow(clippy::print_stderr)] fn main() { @@ -20,13 +30,66 @@ fn main() { }; log::info!("Listening on http://{}", config.addr); - let router = TrustedServerApp::routes(); - if let Err(err) = AxumDevServer::with_config(router, config).run() { + let (router, server_timing_enabled) = TrustedServerApp::routes_with_server_timing_flag(); + if let Err(err) = run(router, server_timing_enabled, config) { log::error!("trusted-server-adapter-axum failed: {err}"); std::process::exit(1); } } +/// Runs the Axum dev server with the request-phase timing terminal layer +/// ([`trusted_server_adapter_axum::timing::TimingService`]) wrapped around +/// `EdgeZeroAxumService`, ahead of `axum::serve`. +/// +/// This does not use `edgezero_adapter_axum::dev_server::AxumDevServer::run`: +/// that helper only accepts a bare [`RouterService`] and builds its own +/// `EdgeZeroAxumService` and `axum::Router` internally, with no seam for an +/// outer service wrapper. Router-generated 404/405 responses bypass +/// `RouterBuilder::middleware` (see `trusted_server_adapter_axum::timing`), +/// so the freeze point has to wrap the tower `Service` boundary itself. +/// Driving `axum::serve` directly here mirrors that helper's own internal +/// bind/wrap/serve/shutdown sequence closely enough to keep behavior +/// identical for callers (`PORT` env var, ctrl-c graceful shutdown). +/// +/// # Errors +/// +/// Returns an error if the Tokio runtime fails to start, the listener fails +/// to bind, or the underlying serve loop errors. +fn run( + router: RouterService, + server_timing_enabled: bool, + config: AxumDevServerConfig, +) -> std::io::Result<()> { + let runtime = RuntimeBuilder::new_multi_thread().enable_all().build()?; + runtime.block_on(serve(router, server_timing_enabled, config)) +} + +async fn serve( + router: RouterService, + server_timing_enabled: bool, + config: AxumDevServerConfig, +) -> std::io::Result<()> { + let listener = TcpListener::bind(config.addr).await?; + + let service = TimingService::new(EdgeZeroAxumService::new(router), server_timing_enabled); + let axum_router = Router::new().fallback_service(service_fn(move |req| { + let mut svc = service.clone(); + async move { svc.call(req).await } + })); + let make_service = axum_router.into_make_service_with_connect_info::(); + + let server = axum::serve(listener, make_service); + if config.enable_ctrl_c { + server + .with_graceful_shutdown(async { + let _ctrl_c = signal::ctrl_c().await; + }) + .await + } else { + server.await + } +} + /// Read a port number from the `PORT` environment variable. /// /// Returns `None` when the variable is unset. Exits non-zero if the value diff --git a/crates/trusted-server-adapter-axum/src/timing.rs b/crates/trusted-server-adapter-axum/src/timing.rs new file mode 100644 index 000000000..832823c15 --- /dev/null +++ b/crates/trusted-server-adapter-axum/src/timing.rs @@ -0,0 +1,242 @@ +//! Terminal timing layer for the Axum dev server. +//! +//! [`TimingService`](crate::timing::TimingService) wraps the tower `Service` +//! boundary the Axum dev server's router sits behind: it creates a +//! [`RequestTimings`](trusted_server_core::request_timing::RequestTimings) +//! collector per request, threads it through request extensions so +//! downstream core handlers can record into it, and on the way back stamps +//! `mark_headers_ready` and appends the `Server-Timing` header via +//! [`append_server_timing_if_private`](trusted_server_core::request_timing::append_server_timing_if_private). +//! +//! This wraps *outside* `RouterService` rather than registering as +//! `RouterBuilder::middleware`. A router-generated 404/405 short-circuits +//! `RouterInner::dispatch` before its middleware chain ever runs, so +//! middleware never sees those responses. By the time a response reaches +//! this layer -- after `RouterService::oneshot` inside +//! `EdgeZeroAxumService::call` has already converted any dispatch error into +//! a plain response -- every response is covered uniformly, router-generated +//! or not. +//! +//! `/health` is excluded by path match before a +//! [`RequestTimings`](trusted_server_core::request_timing::RequestTimings) +//! collector is even created: health checks never carry timing data on any +//! adapter. +//! +//! Unlike the Fastly adapter (state built per request, adding +//! `Phase::AppBuild` to the rendered header), the Axum dev server builds its +//! application state once at startup. There is no per-request app-build +//! interval to measure, so `ts-appbuild` never appears in the header here. + +use std::convert::Infallible; +use std::future::Future; +use std::pin::Pin; +use std::task::{Context, Poll}; + +use axum::body::Body as AxumBody; +use axum::http::{Request, Response}; +use tower::Service; +use trusted_server_core::request_timing::{RequestTimings, append_server_timing_if_private}; + +/// Path excluded from timing collection and `Server-Timing` emission: health +/// checks never carry timing data on any adapter. +const HEALTH_PATH: &str = "/health"; + +/// Wraps an inner Axum tower service with the request-phase timing freeze +/// point described in the module docs. +#[derive(Clone)] +pub struct TimingService { + inner: S, + server_timing_enabled: bool, +} + +impl TimingService { + /// Wraps `inner`, appending `Server-Timing` when `server_timing_enabled` + /// is set and the response is conclusively private. + #[must_use] + pub fn new(inner: S, server_timing_enabled: bool) -> Self { + Self { + inner, + server_timing_enabled, + } + } +} + +impl Service> for TimingService +where + S: Service, Response = Response, Error = Infallible> + + Clone + + Send + + 'static, + S::Future: Send + 'static, +{ + type Error = Infallible; + type Future = Pin> + Send>>; + type Response = Response; + + fn call(&mut self, mut req: Request) -> Self::Future { + let mut inner = self.inner.clone(); + + // Excluded before a collector is even created: `/health` never + // carries timing data, on any adapter. + if req.uri().path() == HEALTH_PATH { + return Box::pin(async move { inner.call(req).await }); + } + + let server_timing_enabled = self.server_timing_enabled; + let timings = RequestTimings::new(); + req.extensions_mut().insert(timings.clone()); + + Box::pin(async move { + let mut response = inner.call(req).await?; + append_server_timing_if_private(&mut response, &timings, server_timing_enabled); + Ok(response) + }) + } + + fn poll_ready(&mut self, cx: &mut Context<'_>) -> Poll> { + self.inner.poll_ready(cx) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use axum::http::header::CACHE_CONTROL; + use axum::http::{HeaderValue, StatusCode}; + use edgezero_adapter_axum::service::EdgeZeroAxumService; + use edgezero_core::body::Body as EdgeBody; + use edgezero_core::context::RequestContext; + use edgezero_core::error::EdgeError; + use edgezero_core::http::response_builder; + use edgezero_core::router::RouterService; + use tower::{ServiceExt as _, service_fn}; + + /// Builds a private (`cache-control: private, no-store`) response for a + /// handler under test. + fn private_ok_response() -> Result { + Ok(response_builder() + .status(StatusCode::OK) + .header("cache-control", "private, no-store") + .body(EdgeBody::from("ok")) + .expect("should build a private response fixture")) + } + + /// Reads a response header as a UTF-8 string, or `None` if absent. + fn header(response: &Response, name: &str) -> Option { + response + .headers() + .get(name) + .and_then(|value| value.to_str().ok()) + .map(ToOwned::to_owned) + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn axum_emits_header_on_private_response() { + let router = RouterService::builder() + .get("/private", |_ctx: RequestContext| async { + private_ok_response() + }) + .build(); + let mut service = TimingService::new(EdgeZeroAxumService::new(router), true); + + let request = Request::builder() + .uri("/private") + .body(AxumBody::empty()) + .expect("should build request"); + let response = service + .ready() + .await + .expect("should be ready") + .call(request) + .await + .expect("should not fail"); + + let server_timing = header(&response, "server-timing").expect("should emit header"); + assert!( + server_timing.contains("ts-total;dur="), + "should carry the collected total: {server_timing}" + ); + assert!( + !server_timing.contains("ts-appbuild"), + "the Axum dev server builds state once at startup, so there is no \ + per-request app-build interval to render: {server_timing}" + ); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn axum_404_carries_header_when_private() { + // An empty router has no routes at all, so any path dispatches + // through `RouterInner::dispatch`'s `NotFound` branch -- exactly the + // path that bypasses `RouterBuilder::middleware`. The router's own + // `EdgeError::into_response` does not attach `Cache-Control`, so a + // small wrapping service forces the response private here, standing + // in for whatever upstream layer would normally mark a genuinely + // private 404. This proves the freeze point still runs for a + // router-generated response without weakening + // `append_server_timing_if_private`'s real gating logic. + let empty_router = RouterService::builder().build(); + let inner = EdgeZeroAxumService::new(empty_router); + let force_private = service_fn(move |req: Request| { + let mut svc = inner.clone(); + async move { + let mut response = svc.call(req).await?; + response + .headers_mut() + .insert(CACHE_CONTROL, HeaderValue::from_static("private, no-store")); + Ok::<_, Infallible>(response) + } + }); + let mut service = TimingService::new(force_private, true); + + let request = Request::builder() + .uri("/does-not-exist") + .body(AxumBody::empty()) + .expect("should build request"); + let response = service + .ready() + .await + .expect("should be ready") + .call(request) + .await + .expect("should not fail"); + + assert_eq!( + response.status(), + StatusCode::NOT_FOUND, + "should still be the router's own not-found response" + ); + let server_timing = header(&response, "server-timing") + .expect("a router-generated 404 must still carry the header when private"); + assert!( + server_timing.contains("ts-total;dur="), + "should carry the collected total: {server_timing}" + ); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn axum_health_is_excluded() { + let router = RouterService::builder() + .get("/health", |_ctx: RequestContext| async { + private_ok_response() + }) + .build(); + let mut service = TimingService::new(EdgeZeroAxumService::new(router), true); + + let request = Request::builder() + .uri("/health") + .body(AxumBody::empty()) + .expect("should build request"); + let response = service + .ready() + .await + .expect("should be ready") + .call(request) + .await + .expect("should not fail"); + + assert!( + header(&response, "server-timing").is_none(), + "/health must never carry a server-timing header" + ); + } +} diff --git a/crates/trusted-server-adapter-fastly/src/app.rs b/crates/trusted-server-adapter-fastly/src/app.rs index 41e5e65ee..3a4ceda8f 100644 --- a/crates/trusted-server-adapter-fastly/src/app.rs +++ b/crates/trusted-server-adapter-fastly/src/app.rs @@ -98,6 +98,7 @@ use edgezero_core::http::{ }; use edgezero_core::router::RouterService; use error_stack::Report; +use trusted_server_core::access_telemetry::{RouteClass, RouteMetadata, publisher_route_template}; use trusted_server_core::auction::AuctionTelemetrySink; use trusted_server_core::auction::endpoints::handle_auction; use trusted_server_core::auction::{AuctionOrchestrator, build_orchestrator}; @@ -114,12 +115,15 @@ use trusted_server_core::ec::identify::{cors_preflight_identify, handle_identify use trusted_server_core::ec::kv::KvIdentityGraph; use trusted_server_core::ec::registry::PartnerRegistry; use trusted_server_core::error::{IntoHttpResponse as _, TrustedServerError}; +use trusted_server_core::geo::GeoLookupState; use trusted_server_core::http_util::is_navigation_request; use trusted_server_core::integrations::{ IntegrationRegistry, ProxyDispatchInput, RequestFilterEffects, RequestFilterRegistryInput, RequestFilterRegistryOutcome, }; -use trusted_server_core::platform::{ClientInfo, GeoInfo, PlatformKvStore, RuntimeServices}; +use trusted_server_core::platform::{ + ClientInfo, GeoInfo, PlatformKvStore, RuntimeServices, TimedKvStore, +}; use trusted_server_core::proxy::{ AssetProxyCachePolicy, handle_asset_proxy_request, handle_first_party_click, handle_first_party_proxy, handle_first_party_proxy_rebuild, handle_first_party_proxy_sign, @@ -133,6 +137,7 @@ use trusted_server_core::request_signing::{ handle_deactivate_key, handle_rotate_key, handle_trusted_server_discovery, handle_verify_signature, }; +use trusted_server_core::request_timing::{Phase, RequestTimings}; use trusted_server_core::settings::{ProxyAssetRoute, Settings}; use trusted_server_core::settings_data::{ default_config_key, default_config_store_name, get_settings_from_config_store, @@ -220,13 +225,18 @@ fn warn_if_certificate_check_disabled(settings: &Settings) { pub(crate) fn runtime_services_for_consent_route( settings: &Settings, runtime_services: &RuntimeServices, + timings: &RequestTimings, ) -> Result> { let Some(store_name) = settings.consent.consent_store.as_deref() else { return Ok(runtime_services.clone()); }; open_kv_store(store_name) - .map(|store| runtime_services.clone().with_kv_store(store)) + .map(|store| { + let timed_store = + Arc::new(TimedKvStore::new(store, timings.clone())) as Arc; + runtime_services.clone().with_kv_store(timed_store) + }) .map_err(|e| { Report::new(TrustedServerError::KvStore { store_name: store_name.to_string(), @@ -294,6 +304,12 @@ fn uses_dynamic_tsjs_fallback(method: &Method, path: &str) -> bool { *method == Method::GET && path.starts_with("/static/tsjs=") } +/// Coarse route template for every `tsjs` bundle request, used as the +/// `route_template` in the [`RouteMetadata`] attached by the tsjs branch of +/// [`dispatch_fallback`]. Actual filenames vary by module/hash; the prefix +/// alone is the route identity that matters for access telemetry. +const TSJS_ROUTE_TEMPLATE: &str = "/static/tsjs=*"; + // --------------------------------------------------------------------------- // EC request state // --------------------------------------------------------------------------- @@ -355,6 +371,17 @@ impl EcRequestState { services: self.services, } } + + /// Derives the carried [`GeoLookupState`] from this request's geo lookup + /// outcome, so response-phase finalize can reuse it instead of repeating + /// the lookup. `build_ec_request_state` always attempts the lookup, so + /// `None` here means the lookup ran and failed, not that it was skipped. + fn geo_lookup_state(&self) -> GeoLookupState { + match &self.geo_info { + Some(info) => GeoLookupState::Resolved(info.clone()), + None => GeoLookupState::Attempted, + } + } } /// Derives device signals from the request's `User-Agent` header. @@ -410,13 +437,21 @@ fn build_ec_request_state( let eids_cookie = crate::extract_cookie_value(req, COOKIE_TS_EIDS); let sharedid_cookie = crate::extract_cookie_value(req, COOKIE_SHAREDID); - let geo_info = services - .geo() - .lookup(services.client_info().client_ip) - .unwrap_or_else(|e| { - log::warn!("geo lookup failed during EC setup: {e}"); - None - }); + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + let geo_info = { + let _span = timings.span(Phase::Geo); + services + .geo() + .lookup(services.client_info().client_ip) + .unwrap_or_else(|e| { + log::warn!("geo lookup failed during EC setup: {e}"); + None + }) + }; let (ec_context, setup_error) = match EcContext::read_from_request_with_geo(settings, req, services, geo_info.as_ref()) { @@ -430,7 +465,7 @@ fn build_ec_request_state( // Bot gate: suppress KV-backed EC writes for unrecognized clients, except // consent withdrawals. Revocations keep the write path so tombstones stay // authoritative even for privacy-extension-heavy clients. - let kv_graph = crate::maybe_identity_graph(settings); + let kv_graph = crate::identity_graph_with_timing(settings, &timings); let finalize_kv_graph = if setup_error.is_none() && (is_real_browser || ec_consent_withdrawn(ec_context.consent())) { @@ -482,6 +517,18 @@ async fn run_pre_route_filters( req: &mut Request, geo_info: Option<&GeoInfo>, ) -> PreRoute { + // Only recorded when a filter is actually registered, so unconfigured + // deployments omit ts-filter from the Server-Timing header entirely. + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + let _span = state + .registry + .has_request_filters() + .then(|| timings.span(Phase::Filter)); + match state .registry .filter_request(RequestFilterRegistryInput { @@ -515,6 +562,7 @@ fn attach_dispatch_extensions( ec: EcRequestState, effects: RequestFilterEffects, ) -> Response { + response.extensions_mut().insert(ec.geo_lookup_state()); response.extensions_mut().insert(ec.into_finalize_state()); if !effects.response_headers.is_empty() { response.extensions_mut().insert(effects); @@ -551,7 +599,12 @@ async fn execute_named( // Deliberately do not use an EC request-state graph: that // copy is bot-gated, while operators use curl for this // authenticated diagnostic. - let kv = crate::maybe_identity_graph(&state.settings); + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + let kv = crate::identity_graph_with_timing(&state.settings, &timings); handle_admin_ec_lookup(kv.as_ref(), ®istry, &req) } NamedRouteHandler::AdminEidsLookup => handle_admin_eids_lookup(®istry, &req), @@ -622,7 +675,12 @@ async fn run_named_route( if req.method() == Method::OPTIONS { cors_preflight_identify(&state.settings, &req) } else { - let kv = crate::require_identity_graph(&state.settings)?; + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + let kv = crate::require_identity_graph_with_timing(&state.settings, &timings)?; let partner_registry = PartnerRegistry::from_config(&state.settings.ec.partners)?; handle_identify( &state.settings, @@ -639,7 +697,13 @@ async fn run_named_route( // The auction reads consent data, so the consent KV store must be // available — fail closed with 503 when it is configured but // cannot be opened, matching legacy behavior. - let consent_services = runtime_services_for_consent_route(&state.settings, services)?; + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + let consent_services = + runtime_services_for_consent_route(&state.settings, services, &timings)?; let partner_registry = PartnerRegistry::from_config(&state.settings.ec.partners)?; let registry_ref = if partner_registry.is_empty() { None @@ -667,7 +731,13 @@ async fn run_named_route( // Like the auction, page-bids reads consent data, so the consent KV // store must be available — fail closed with 503 when configured but // unopenable, matching legacy. - let consent_services = runtime_services_for_consent_route(&state.settings, services)?; + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + let consent_services = + runtime_services_for_consent_route(&state.settings, services, &timings)?; let partner_registry = PartnerRegistry::from_config(&state.settings.ec.partners)?; let registry_ref = if partner_registry.is_empty() { None @@ -712,12 +782,18 @@ fn run_batch_sync(state: &AppState, services: &RuntimeServices, req: Request) -> let is_real_browser = device_signals.looks_like_browser(); let eids_cookie = crate::extract_cookie_value(&req, COOKIE_TS_EIDS); let sharedid_cookie = crate::extract_cookie_value(&req, COOKIE_SHAREDID); + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); - let result = crate::require_identity_graph(&state.settings).and_then(|kv| { - let partner_registry = PartnerRegistry::from_config(&state.settings.ec.partners)?; - let limiter = FastlyRateLimiter::new(RATE_COUNTER_NAME); - handle_batch_sync(&kv, &partner_registry, &limiter, req) - }); + let result = + crate::require_identity_graph_with_timing(&state.settings, &timings).and_then(|kv| { + let partner_registry = PartnerRegistry::from_config(&state.settings.ec.partners)?; + let limiter = FastlyRateLimiter::new(RATE_COUNTER_NAME); + handle_batch_sync(&kv, &partner_registry, &limiter, req) + }); let mut response = result.unwrap_or_else(|e| http_error(&e)); // Legacy parity: batch-sync responses still pass through @@ -777,12 +853,28 @@ async fn dispatch_fallback( PreRoute::Continue { effects } => effects, }; + // Assigned exactly once, per branch below, alongside the routing + // decision itself, so the access-telemetry route identity always + // reflects which branch actually dispatched the request — including + // when that branch's handler errors. The asset-route sub-branch is an + // early return handled separately by `dispatch_asset_fallback`, so it + // never reaches (or needs to assign) this binding. + let route_metadata: Option; + let result = if uses_dynamic_tsjs_fallback(&method, &path) { + route_metadata = Some(RouteMetadata { + route_class: RouteClass::Tsjs, + route_template: TSJS_ROUTE_TEMPLATE.to_owned(), + }); handle_tsjs_dynamic(&req, &state.registry, EdgeCacheHeader::SurrogateControl) } else if state.registry.has_route(&method, &path) { // Integration-proxy responses are not bounded by // publisher.max_buffered_body_bytes. Publisher fallback below uses the // publisher-specific streaming finalizer instead. + route_metadata = Some(RouteMetadata { + route_class: RouteClass::IntegrationProxy, + route_template: publisher_route_template(&path), + }); state .registry .handle_proxy(ProxyDispatchInput { @@ -810,9 +902,31 @@ async fn dispatch_fallback( .then(|| state.settings.asset_route_for_path(&path)) .flatten(); if let Some(asset_route) = matched_asset_route { - return dispatch_asset_fallback(state, services, req, asset_route, &effects).await; + // The template is the operator-configured route prefix, so it + // is bounded and content-free by construction (unlike request + // paths, which need `publisher_route_template`). + let asset_metadata = RouteMetadata { + route_class: RouteClass::Asset, + route_template: format!("{}/*", asset_route.prefix.trim_end_matches('/')), + }; + let mut response = dispatch_asset_fallback( + state, + services, + req, + asset_route, + &effects, + ec.geo_lookup_state(), + ) + .await; + response.extensions_mut().insert(asset_metadata); + return response; } + route_metadata = Some(RouteMetadata { + route_class: RouteClass::PublisherHtml, + route_template: publisher_route_template(&path), + }); + // Generate an EC ID if needed — mirrors the legacy catch-all arm. // Only for document navigations by recognised browsers; subresource // requests may lack consent signals such as Sec-GPC. @@ -828,7 +942,12 @@ async fn dispatch_fallback( // Publisher pages read consent data, so the consent KV store must be // available — fail closed with 503 when it is configured but cannot // be opened, matching legacy behavior. - match runtime_services_for_consent_route(&state.settings, services) { + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + match runtime_services_for_consent_route(&state.settings, services, &timings) { Ok(publisher_services) => { // Run the server-side auction with the configured creative- // opportunity slots and collect dispatched bids from the lazy @@ -876,7 +995,10 @@ async fn dispatch_fallback( } }; - let response = result.unwrap_or_else(|e| http_error(&e)); + let mut response = result.unwrap_or_else(|e| http_error(&e)); + if let Some(metadata) = route_metadata { + response.extensions_mut().insert(metadata); + } attach_dispatch_extensions(response, ec, effects) } @@ -900,7 +1022,10 @@ fn asset_response_carries_body(method: &Method, status: StatusCode) -> bool { /// [`AssetProxyCachePolicy`] out via response extensions so `edgezero_main` /// can reapply protected cache directives after finalization. EC finalization /// is intentionally skipped: no [`EcFinalizeState`] is attached, matching the -/// legacy `should_finalize_ec = false` behavior for asset responses. +/// legacy `should_finalize_ec = false` behavior for asset responses. The +/// caller's [`GeoLookupState`] is still attached, since `build_ec_request_state` +/// already attempted the lookup before the asset route was matched — this is +/// the one exit path that carries geo state without an `EcFinalizeState`. /// /// Like legacy `route_request`, asset bodies are streamed straight to the client /// with no cap: the origin stream is attached to the response and `edgezero_main` @@ -915,6 +1040,7 @@ async fn dispatch_asset_fallback( req: Request, asset_route: &ProxyAssetRoute, effects: &RequestFilterEffects, + geo_state: GeoLookupState, ) -> Response { log::info!("No explicit route matched; proxying via configured asset route"); @@ -936,6 +1062,7 @@ async fn dispatch_asset_fallback( } response.extensions_mut().insert(cache_policy); + response.extensions_mut().insert(geo_state); attach_request_filter_effects(&mut response, effects); response } @@ -944,6 +1071,7 @@ async fn dispatch_asset_fallback( response .extensions_mut() .insert(AssetProxyCachePolicy::NoStorePrivate); + response.extensions_mut().insert(geo_state); attach_request_filter_effects(&mut response, effects); response } @@ -1066,6 +1194,10 @@ struct NamedRoute { path: &'static str, primary_methods: &'static [Method], handler: NamedRouteHandler, + /// Access-telemetry traffic category for this row. Attached verbatim + /// alongside `path` (the route-table pattern) to every response this + /// route produces — see [`named_route_handler`]. + route_class: RouteClass, } const LEGACY_ADMIN_DENY_METHODS: &[Method] = &[ @@ -1083,21 +1215,25 @@ const NAMED_ROUTES: &[NamedRoute] = &[ path: "/.well-known/trusted-server.json", primary_methods: &[Method::GET], handler: NamedRouteHandler::TrustedServerDiscovery, + route_class: RouteClass::Other, }, NamedRoute { path: "/verify-signature", primary_methods: &[Method::POST], handler: NamedRouteHandler::VerifySignature, + route_class: RouteClass::Ec, }, NamedRoute { path: "/_ts/admin/keys/rotate", primary_methods: &[Method::POST], handler: NamedRouteHandler::RotateKey, + route_class: RouteClass::Ec, }, NamedRoute { path: "/_ts/admin/keys/deactivate", primary_methods: &[Method::POST], handler: NamedRouteHandler::DeactivateKey, + route_class: RouteClass::Ec, }, // Admin EC lookup: the bare route reads the EC ID from the caller's // `ts-ec` cookie; the parameterized route takes an explicit EC ID. @@ -1105,11 +1241,13 @@ const NAMED_ROUTES: &[NamedRoute] = &[ path: "/_ts/admin/ec", primary_methods: &[Method::GET], handler: NamedRouteHandler::AdminEcLookup, + route_class: RouteClass::Ec, }, NamedRoute { path: "/_ts/admin/ec/{id}", primary_methods: &[Method::GET], handler: NamedRouteHandler::AdminEcLookup, + route_class: RouteClass::Ec, }, // Admin EIDs echo: decodes the request's ts-eids/sharedId cookies with // an ingestion preview. Pure request inspection — no KV access. @@ -1117,6 +1255,7 @@ const NAMED_ROUTES: &[NamedRoute] = &[ path: "/_ts/admin/eids", primary_methods: &[Method::GET], handler: NamedRouteHandler::AdminEidsLookup, + route_class: RouteClass::Ec, }, // The legacy non-`/_ts` aliases (`/admin/keys/*`) are denied locally with a // 404 instead of executing key operations: the production basic-auth handler @@ -1128,36 +1267,43 @@ const NAMED_ROUTES: &[NamedRoute] = &[ path: "/admin/keys/rotate", primary_methods: LEGACY_ADMIN_DENY_METHODS, handler: NamedRouteHandler::LegacyAdminDenied, + route_class: RouteClass::Other, }, NamedRoute { path: "/admin/keys/deactivate", primary_methods: LEGACY_ADMIN_DENY_METHODS, handler: NamedRouteHandler::LegacyAdminDenied, + route_class: RouteClass::Other, }, NamedRoute { path: "/_ts/api/v1/batch-sync", primary_methods: &[Method::POST], handler: NamedRouteHandler::BatchSync, + route_class: RouteClass::Ec, }, NamedRoute { path: "/_ts/api/v1/identify", primary_methods: &[Method::GET, Method::OPTIONS], handler: NamedRouteHandler::Identify, + route_class: RouteClass::Ec, }, NamedRoute { path: "/_ts/set-tester", primary_methods: &[Method::GET], handler: NamedRouteHandler::SetTester, + route_class: RouteClass::Other, }, NamedRoute { path: "/_ts/clear-tester", primary_methods: &[Method::GET], handler: NamedRouteHandler::ClearTester, + route_class: RouteClass::Other, }, NamedRoute { path: "/auction", primary_methods: &[Method::POST], handler: NamedRouteHandler::Auction, + route_class: RouteClass::AuctionApi, }, // GET runs the SPA re-auction; OPTIONS is denied in-handler as a CORS // preflight guard for this side-effecting endpoint. @@ -1165,6 +1311,7 @@ const NAMED_ROUTES: &[NamedRoute] = &[ path: PAGE_BIDS_PATH, primary_methods: &[Method::GET, Method::OPTIONS], handler: NamedRouteHandler::PageBids, + route_class: RouteClass::AuctionApi, }, // Deprecated double-underscore alias. tsjs bundles served before the // `/_ts/page-bids` rename keep requesting this path from already-loaded @@ -1175,21 +1322,29 @@ const NAMED_ROUTES: &[NamedRoute] = &[ path: PAGE_BIDS_LEGACY_PATH, primary_methods: &[Method::GET, Method::OPTIONS], handler: NamedRouteHandler::PageBids, + route_class: RouteClass::AuctionApi, }, + // Classified `Other` rather than `IntegrationProxy`: that class is + // reserved for `state.registry.handle_proxy` (the js-integration proxy + // dispatch in `dispatch_fallback`), which these first-party proxy routes + // do not go through. NamedRoute { path: "/first-party/proxy", primary_methods: &[Method::GET], handler: NamedRouteHandler::FirstPartyProxy, + route_class: RouteClass::Other, }, NamedRoute { path: "/first-party/click", primary_methods: &[Method::GET], handler: NamedRouteHandler::FirstPartyClick, + route_class: RouteClass::Other, }, NamedRoute { path: "/first-party/sign", primary_methods: &[Method::GET, Method::POST], handler: NamedRouteHandler::FirstPartySign, + route_class: RouteClass::Other, }, NamedRoute { path: "/first-party/proxy-rebuild", @@ -1198,16 +1353,35 @@ const NAMED_ROUTES: &[NamedRoute] = &[ // POST is blocked by CORS and the guard navigates here for a 302 instead. primary_methods: &[Method::GET, Method::POST], handler: NamedRouteHandler::FirstPartyProxyRebuild, + route_class: RouteClass::Other, }, ]; +/// Wraps [`execute_named`], attaching a [`RouteMetadata`] extension carrying +/// `route_class` and the route-table pattern (`route_template`, verbatim, +/// with parameters left as placeholders) to every response the handler +/// produces — including its early-return diagnostic and setup-error arms, +/// since the attachment happens once around the whole future rather than in +/// each branch. fn named_route_handler( state: Arc, handler: NamedRouteHandler, + route_class: RouteClass, + route_template: &'static str, ) -> impl Fn(RequestContext) -> HandlerFuture + Clone + Send + Sync + 'static { move |ctx: RequestContext| { let state = Arc::clone(&state); - Box::pin(execute_named(state, ctx, handler)) + Box::pin(async move { + execute_named(state, ctx, handler) + .await + .map(|mut response| { + response.extensions_mut().insert(RouteMetadata { + route_class, + route_template: route_template.to_owned(), + }); + response + }) + }) } } @@ -1266,7 +1440,12 @@ impl TrustedServerApp { router = router.route( route.path, method.clone(), - named_route_handler(Arc::clone(state), route.handler), + named_route_handler( + Arc::clone(state), + route.handler, + route.route_class, + route.path, + ), ); } @@ -1304,35 +1483,41 @@ mod tests { use super::{ AppState, NAMED_ROUTES, NamedRouteHandler, PAGE_BIDS_LEGACY_PATH, PAGE_BIDS_PATH, - TrustedServerApp, build_per_request_services, build_state_from_settings, + RouteClass, RouteMetadata, TSJS_ROUTE_TEMPLATE, TrustedServerApp, + build_per_request_services, build_state_from_settings, publisher_route_template, startup_error_router, }; use base64::Engine as _; use bytes::Bytes; use edgezero_core::body::Body; use edgezero_core::context::RequestContext; - use edgezero_core::http::{Method, Response, StatusCode, header, request_builder}; + use edgezero_core::http::{ + Method, Response, StatusCode, header, request_builder, response_builder, + }; use edgezero_core::key_value_store::NoopKvStore; use edgezero_core::params::PathParams; use edgezero_core::router::RouterService; use std::net::{IpAddr, Ipv4Addr}; use std::sync::Mutex; + use std::sync::atomic::{AtomicUsize, Ordering}; use error_stack::Report; use futures::executor::block_on; use serde_json::json; - use trusted_server_core::constants::HEADER_X_GEO_INFO_AVAILABLE; + use trusted_server_core::constants::{HEADER_X_GEO_COUNTRY, HEADER_X_GEO_INFO_AVAILABLE}; use trusted_server_core::ec::device::DeviceSignals; use trusted_server_core::error::TrustedServerError; + use trusted_server_core::geo::GeoLookupState; use trusted_server_core::integrations::{ HeaderMutation, IntegrationRegistry, IntegrationRequestFilter, RequestFilterDecision, RequestFilterEffects, RequestFilterInput, }; use trusted_server_core::platform::{ - ClientInfo, PlatformBackend, PlatformBackendSpec, PlatformError, PlatformHttpClient, - PlatformHttpRequest, PlatformKvStore, PlatformPendingRequest, PlatformResponse, - PlatformSelectResult, RuntimeServices, + ClientInfo, GeoInfo, PlatformBackend, PlatformBackendSpec, PlatformError, PlatformGeo, + PlatformHttpClient, PlatformHttpRequest, PlatformKvStore, PlatformPendingRequest, + PlatformResponse, PlatformSelectResult, RuntimeServices, }; + use trusted_server_core::request_timing::RequestTimings; use trusted_server_core::settings::Settings; fn settings_with_missing_consent_store() -> Settings { @@ -1478,19 +1663,19 @@ mod tests { ); } - /// Builds a router whose `AppState` uses a registry containing the given - /// request filters (and no routes), so dispatch-level request-filter - /// behavior can be exercised without a real integration. - fn router_with_request_filters( + /// Builds an `AppState` whose registry contains the given request + /// filters (and no routes), so dispatch-level request-filter behavior can + /// be exercised without a real integration. + fn state_with_request_filters( filters: Vec>, - ) -> RouterService { + ) -> Arc { let settings = test_settings(); let orchestrator = trusted_server_core::auction::build_orchestrator(&settings) .expect("should build orchestrator"); let registry = IntegrationRegistry::from_request_filters(filters); let default_kv_store = Arc::new(crate::platform::UnavailableKvStore) as Arc; - let state = Arc::new(super::AppState { + Arc::new(super::AppState { auction_telemetry_sink: Arc::new( trusted_server_core::auction::NoopAuctionTelemetrySink, ), @@ -1498,8 +1683,15 @@ mod tests { orchestrator: Arc::new(orchestrator), registry: Arc::new(registry), default_kv_store, - }); - TrustedServerApp::routes_for_state(&state) + }) + } + + /// Builds a router on top of [`state_with_request_filters`] so + /// dispatch-level request-filter behavior can be exercised end-to-end. + fn router_with_request_filters( + filters: Vec>, + ) -> RouterService { + TrustedServerApp::routes_for_state(&state_with_request_filters(filters)) } /// Continues routing while mutating the request and emitting a response @@ -2123,6 +2315,111 @@ mod tests { ); } + /// `Authorization: Basic` header value for `test_settings()`'s + /// `^/_ts/admin` handler (`admin` / `admin-pass`). + fn admin_basic_auth_header() -> edgezero_core::http::HeaderValue { + let credentials = base64::engine::general_purpose::STANDARD.encode("admin:admin-pass"); + format!("Basic {credentials}") + .parse() + .expect("should parse basic-auth header value") + } + + #[test] + fn named_route_attaches_the_table_pattern_verbatim_even_with_a_real_id_in_the_path() { + // A named-route response must carry the route-TABLE pattern + // (`{id}` left as a placeholder), never the caller's actual matched + // path segment — this is what keeps a real EC identifier out of + // access telemetry, independent of anything the row-serialization + // layer does. + let router = test_router(); + let ec_id = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.test01"; + let mut req = empty_request(Method::GET, &format!("/_ts/admin/ec/{ec_id}")); + req.headers_mut() + .insert(header::AUTHORIZATION, admin_basic_auth_header()); + let response = route(&router, req); + + let metadata = response + .extensions() + .get::() + .expect("named-route responses should carry RouteMetadata"); + assert_eq!(metadata.route_class, RouteClass::Ec); + assert_eq!(metadata.route_template, "/_ts/admin/ec/{id}"); + assert!( + !metadata.route_template.contains(ec_id), + "the attached template must never contain the matched id" + ); + } + + #[test] + fn named_route_attaches_metadata_even_on_a_read_only_diagnostic_early_return() { + // AdminEidsLookup is handled by an early-return arm inside + // execute_named, before the normal EC lifecycle runs (see the + // "read-only diagnostics" comment there). named_route_handler wraps + // the whole future, so the attachment must still happen here too. + let router = test_router(); + let mut req = empty_request(Method::GET, "/_ts/admin/eids"); + req.headers_mut() + .insert(header::AUTHORIZATION, admin_basic_auth_header()); + let response = route(&router, req); + + let metadata = response + .extensions() + .get::() + .expect("even a read-only diagnostic early-return response should carry RouteMetadata"); + assert_eq!(metadata.route_class, RouteClass::Ec); + assert_eq!(metadata.route_template, "/_ts/admin/eids"); + } + + #[test] + fn tsjs_fallback_attaches_tsjs_route_metadata() { + let router = test_router(); + let response = route( + &router, + empty_request(Method::GET, "/static/tsjs=tsjs-unified.min.js"), + ); + + let metadata = response + .extensions() + .get::() + .expect("tsjs fallback responses should carry RouteMetadata"); + assert_eq!(metadata.route_class, RouteClass::Tsjs); + assert_eq!(metadata.route_template, TSJS_ROUTE_TEMPLATE); + } + + #[test] + fn integration_proxy_fallback_attaches_integration_proxy_route_metadata() { + // test_settings() enables the prebid integration, which registers a + // proxy route at /integrations/prebid/bundle.js. + let router = test_router(); + let response = route( + &router, + empty_request(Method::GET, "/integrations/prebid/bundle.js"), + ); + + let metadata = response + .extensions() + .get::() + .expect("integration-proxy fallback responses should carry RouteMetadata"); + assert_eq!(metadata.route_class, RouteClass::IntegrationProxy); + assert_eq!( + metadata.route_template, + publisher_route_template("/integrations/prebid/bundle.js") + ); + } + + #[test] + fn publisher_fallback_attaches_publisher_html_route_metadata() { + let router = test_router(); + let response = route(&router, empty_request(Method::GET, "/news/some-article")); + + let metadata = response + .extensions() + .get::() + .expect("publisher fallback responses should carry RouteMetadata"); + assert_eq!(metadata.route_class, RouteClass::PublisherHtml); + assert_eq!(metadata.route_template, "/news/*"); + } + #[test] fn browser_device_signals_from_extension_reach_ec_finalize_state() { // Regression guard for the EdgeZero JA4/H2 signal loss: `edgezero_main` @@ -2529,6 +2826,61 @@ mod tests { ); } + #[test] + fn asset_fallback_carries_geo_state_without_ec_finalize_state() { + // The asset-route fallback is the one exit path that skips + // EcFinalizeState but must still carry GeoLookupState, since + // build_ec_request_state (and its geo lookup) already ran before the + // asset route was matched. Without this, the finalize step would + // silently repeat the lookup for every asset request. + let settings = Settings::from_toml( + r#" + [[handlers]] + path = "^/_ts/admin" + username = "admin" + password = "admin-pass" + + [publisher] + domain = "test-publisher.com" + cookie_domain = ".test-publisher.com" + origin_url = "https://origin.test-publisher.com" + proxy_secret = "unit-test-proxy-secret" + + [ec] + passphrase = "test-secret-key-32-bytes-minimum" + + [request_signing] + enabled = false + config_store_id = "test-config-store-id" + secret_store_id = "test-secret-store-id" + + [proxy] + + [[proxy.asset_routes]] + prefix = "/.image/" + origin_url = "https://assets.example.com" + "#, + ) + .expect("should parse asset-route settings"); + let state = build_state_from_settings(settings).expect("should build state"); + let router = TrustedServerApp::routes_for_state(&state); + + let response = route(&router, empty_request(Method::GET, "/.image/banner.png")); + + assert!( + response.extensions().get::().is_some(), + "asset-route responses should still carry GeoLookupState even though \ + EC finalization is skipped" + ); + assert!( + response + .extensions() + .get::() + .is_none(), + "asset-route responses must skip EC finalization (no EcFinalizeState)" + ); + } + struct FixedBackend; impl PlatformBackend for FixedBackend { @@ -2649,6 +3001,7 @@ mod tests { req, asset_route, &effects, + trusted_server_core::geo::GeoLookupState::NotAttempted, )); assert_eq!( @@ -2692,6 +3045,259 @@ mod tests { ); } + /// A [`PlatformGeo`] stub that counts every `lookup` call and always + /// returns the same canned result, used to prove the request-phase geo + /// lookup is never repeated during finalize. + struct CountingGeo { + calls: Arc, + result: Option, + } + + impl PlatformGeo for CountingGeo { + fn lookup(&self, _: Option) -> Result, Report> { + self.calls.fetch_add(1, Ordering::SeqCst); + Ok(self.result.clone()) + } + } + + fn sample_geo_info() -> GeoInfo { + GeoInfo { + city: "Testville".to_string(), + country: "US".to_string(), + continent: "NorthAmerica".to_string(), + latitude: 0.0, + longitude: 0.0, + metro_code: 0, + region: None, + asn: None, + } + } + + fn runtime_services_with_geo(geo: Arc) -> RuntimeServices { + RuntimeServices::builder() + .config_store(Arc::new(crate::platform::FastlyPlatformConfigStore)) + .secret_store(Arc::new(crate::platform::FastlyPlatformSecretStore)) + .kv_store(Arc::new(NoopKvStore) as Arc) + .backend(Arc::new(FixedBackend)) + .http_client(Arc::new(StreamingHttpClient)) + .geo(geo) + .client_info(ClientInfo::default()) + .build() + } + + #[test] + fn finalize_reuses_request_phase_geo_without_second_lookup() { + // Dispatching a publisher route runs build_ec_request_state, which + // attempts the geo lookup once and carries the result via + // GeoLookupState. The finalize step (resolve_geo_for_response) must + // reuse that carried value instead of calling the geo backend again. + let calls = Arc::new(AtomicUsize::new(0)); + let geo = Arc::new(CountingGeo { + calls: Arc::clone(&calls), + result: Some(sample_geo_info()), + }); + let state = app_state_for_settings(test_settings()); + let services = runtime_services_with_geo(geo); + let req = empty_request(Method::GET, "/some-page"); + + let response = block_on(super::dispatch_fallback(&state, &services, req)); + + let carried = response + .extensions() + .get::() + .cloned() + .expect("dispatch should attach GeoLookupState"); + assert!( + matches!(carried, GeoLookupState::Resolved(_)), + "a successful lookup should carry Resolved" + ); + + let geo_info = + crate::middleware::resolve_geo_for_response(&response, &carried, None, |_| { + panic!("finalize must not repeat a resolved geo lookup"); + }); + + assert_eq!( + calls.load(Ordering::SeqCst), + 1, + "only the request-phase lookup should have run" + ); + + let mut response = response; + geo_info + .expect("geo info should have resolved") + .set_response_headers(&mut response); + assert!( + response.headers().get(HEADER_X_GEO_COUNTRY).is_some(), + "x-geo-country should still be set on the response after reusing the carried geo" + ); + } + + #[test] + fn failed_lookup_is_not_retried() { + // When the request-phase lookup fails (returns None), dispatch must + // carry GeoLookupState::Attempted rather than NotAttempted, and + // finalize must not retry it. + let calls = Arc::new(AtomicUsize::new(0)); + let geo = Arc::new(CountingGeo { + calls: Arc::clone(&calls), + result: None, + }); + let state = app_state_for_settings(test_settings()); + let services = runtime_services_with_geo(geo); + let req = empty_request(Method::GET, "/some-page"); + + let response = block_on(super::dispatch_fallback(&state, &services, req)); + + let carried = response + .extensions() + .get::() + .cloned() + .expect("dispatch should attach GeoLookupState even for a failed lookup"); + assert!( + matches!(carried, GeoLookupState::Attempted), + "a failed lookup should carry Attempted, not Resolved or NotAttempted" + ); + + let geo_info = + crate::middleware::resolve_geo_for_response(&response, &carried, None, |_| { + panic!("finalize must not retry a failed geo lookup"); + }); + + assert_eq!( + calls.load(Ordering::SeqCst), + 1, + "only the request-phase lookup should have run" + ); + assert!( + geo_info.is_none(), + "no geo info should be available after a failed lookup" + ); + } + + #[test] + fn filter_span_recorded_when_request_filter_runs() { + // The Filter phase span should only be recorded when the registry + // actually has a request filter registered, so unconfigured + // deployments omit ts-filter from the Server-Timing header entirely. + let state = state_with_request_filters(vec![Arc::new(RecordingRequestFilter)]); + let services = RuntimeServices::builder() + .config_store(Arc::new(crate::platform::FastlyPlatformConfigStore)) + .secret_store(Arc::new(crate::platform::FastlyPlatformSecretStore)) + .kv_store(Arc::new(NoopKvStore) as Arc) + .backend(Arc::new(FixedBackend)) + .http_client(Arc::new(StreamingHttpClient)) + .geo(Arc::new(crate::platform::FastlyPlatformGeo)) + .client_info(ClientInfo::default()) + .build(); + let mut req = empty_request(Method::GET, "/some-page"); + let timings = RequestTimings::new(); + req.extensions_mut().insert(timings.clone()); + + let _ = block_on(super::run_pre_route_filters( + &state, &services, &mut req, None, + )); + + assert!( + timings.snapshot().filter_ms.is_some(), + "should record the Filter phase span when a request filter is registered and runs" + ); + } + + #[test] + fn filter_span_not_recorded_when_no_request_filters_registered() { + // Mirror test: an empty registry must never record the Filter span, + // even though run_pre_route_filters still runs (as a no-op loop). + let state = state_with_request_filters(Vec::new()); + let services = RuntimeServices::builder() + .config_store(Arc::new(crate::platform::FastlyPlatformConfigStore)) + .secret_store(Arc::new(crate::platform::FastlyPlatformSecretStore)) + .kv_store(Arc::new(NoopKvStore) as Arc) + .backend(Arc::new(FixedBackend)) + .http_client(Arc::new(StreamingHttpClient)) + .geo(Arc::new(crate::platform::FastlyPlatformGeo)) + .client_info(ClientInfo::default()) + .build(); + let mut req = empty_request(Method::GET, "/some-page"); + let timings = RequestTimings::new(); + req.extensions_mut().insert(timings.clone()); + + let _ = block_on(super::run_pre_route_filters( + &state, &services, &mut req, None, + )); + + assert!( + timings.snapshot().filter_ms.is_none(), + "should omit the Filter phase span when no request filters are registered" + ); + } + + fn settings_with_consent_and_ec_store() -> Settings { + Settings::from_toml( + r#" + [[handlers]] + path = "^/_ts/admin" + username = "admin" + password = "admin-pass" + + [publisher] + domain = "test-publisher.com" + cookie_domain = ".test-publisher.com" + origin_url = "https://origin.test-publisher.com" + proxy_secret = "unit-test-proxy-secret" + + [ec] + passphrase = "test-secret-key-32-bytes-minimum" + ec_store = "ec_identity_store" + + [consent] + consent_store = "consent_store" + + [request_signing] + enabled = false + config_store_id = "test-config-store-id" + secret_store_id = "test-secret-store-id" + "#, + ) + .expect("should parse settings with consent and EC KV stores configured") + } + + #[test] + fn consent_store_reads_are_timed_and_pull_sync_is_not() { + // Consent-store access threaded through RuntimeServices uses the same + // TimedKvStore decorator as request-path KvIdentityGraph + // construction, so a read through it records Phase::EcKv. + let settings = settings_with_consent_and_ec_store(); + let services = streaming_runtime_services(); + let timings = RequestTimings::new(); + + let consent_services = + super::runtime_services_for_consent_route(&settings, &services, &timings) + .expect("should open the configured consent store"); + let _ = block_on(consent_services.kv_store().get_bytes("consent-read-key")); + + timings.mark_headers_ready(); + assert!( + timings.snapshot().kv_ms.is_some(), + "a consent-store read through the decorated RuntimeServices store should record Phase::EcKv" + ); + + // Pull-sync's identity graph is built by `require_identity_graph`, + // which takes no `timings` parameter at all — the untimed store it + // constructs cannot record into any handle, including a fresh one. + let graph = crate::require_identity_graph(&settings) + .expect("should construct the pull-sync identity graph"); + let ec_id = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.test01"; + let _ = graph.get(ec_id); + + let pull_sync_timings = RequestTimings::new(); + pull_sync_timings.mark_headers_ready(); + assert!( + pull_sync_timings.snapshot().kv_ms.is_none(), + "pull-sync's untimed graph construction has no timings handle to record into" + ); + } + #[test] fn dispatch_runs_request_filter_and_threads_response_effects() { // Regression guard for the EdgeZero request-filter bypass: the publisher @@ -2750,4 +3356,108 @@ mod tests { "the filter's response-header effect must be threaded out" ); } + + /// Joins every instance of a response header into one comma-separated + /// string (mirroring how a client sees repeated header fields), or + /// `None` if the header is absent. + fn response_header(response: &Response, name: &str) -> Option { + let values: Vec<&str> = response + .headers() + .get_all(name) + .iter() + .filter_map(|value| value.to_str().ok()) + .collect(); + if values.is_empty() { + None + } else { + Some(values.join(", ")) + } + } + + #[test] + fn server_timing_emitted_on_private_response_when_enabled() { + let mut response = response_builder() + .header("cache-control", "private, no-store") + .body(Body::empty()) + .expect("should build a private response fixture"); + let timings = RequestTimings::new(); + + crate::apply_server_timing_header(&mut response, &timings, true); + + let header = response_header(&response, "server-timing").expect("should emit header"); + assert!( + header.contains("ts-total;dur="), + "should carry the stored total: {header}" + ); + assert_eq!( + header.matches("ts-total").count(), + 1, + "should emit exactly one TS-owned metric set" + ); + } + + #[test] + fn server_timing_absent_when_flag_off() { + let mut response = response_builder() + .header("cache-control", "private, no-store") + .body(Body::empty()) + .expect("should build a private response fixture"); + let timings = RequestTimings::new(); + + crate::apply_server_timing_header(&mut response, &timings, false); + + assert!( + response_header(&response, "server-timing").is_none(), + "should not emit server-timing when the flag is off" + ); + } + + #[test] + fn server_timing_absent_on_cacheable_responses() { + // tsjs route policy: public, long max-age, immutable. + let mut tsjs_response = response_builder() + .header("cache-control", "public, max-age=31536000, immutable") + .body(Body::empty()) + .expect("should build a tsjs-style response fixture"); + // A bare shared-cacheable response with no private/no-store directive. + let mut public_response = response_builder() + .header("cache-control", "max-age=60") + .body(Body::empty()) + .expect("should build a bare max-age response fixture"); + + crate::apply_server_timing_header(&mut tsjs_response, &RequestTimings::new(), true); + crate::apply_server_timing_header(&mut public_response, &RequestTimings::new(), true); + + assert!( + response_header(&tsjs_response, "server-timing").is_none(), + "should not emit on the public immutable tsjs cache policy" + ); + assert!( + response_header(&public_response, "server-timing").is_none(), + "should not emit on a bare shared-cacheable max-age response" + ); + } + + #[test] + fn preexisting_server_timing_values_survive() { + let mut response = response_builder() + .header("cache-control", "private, no-store") + .header("server-timing", "upstream;dur=1") + .body(Body::empty()) + .expect("should build a private response fixture carrying an upstream Server-Timing"); + let timings = RequestTimings::new(); + + crate::apply_server_timing_header(&mut response, &timings, true); + + let header = + response_header(&response, "server-timing").expect("should still carry a header"); + assert!( + header.contains("upstream;dur=1"), + "should preserve the pre-existing entry: {header}" + ); + assert!( + header.contains("ts-total"), + "should append the TS-owned set: {header}" + ); + } } diff --git a/crates/trusted-server-adapter-fastly/src/main.rs b/crates/trusted-server-adapter-fastly/src/main.rs index a19d0485d..934f98402 100644 --- a/crates/trusted-server-adapter-fastly/src/main.rs +++ b/crates/trusted-server-adapter-fastly/src/main.rs @@ -1,4 +1,5 @@ use std::sync::Arc; +use std::time::{Instant, SystemTime, UNIX_EPOCH}; use edgezero_adapter_fastly::config_store::FastlyConfigStore as EdgeZeroFastlyConfigStore; use edgezero_adapter_fastly::request::into_core_request; @@ -11,7 +12,13 @@ use error_stack::Report; use fastly::http::Method as FastlyMethod; use fastly::{Request as FastlyRequest, Response as FastlyResponse}; +use trusted_server_core::access_telemetry::{ + AccessTelemetrySnapshot, RouteClass, RouteMetadata, access_event_row, +}; use trusted_server_core::cache_policy::EdgeCacheHeader; +use trusted_server_core::constants::{ + ENV_FASTLY_IS_STAGING, ENV_FASTLY_POP, ENV_FASTLY_SERVICE_ID, ENV_FASTLY_SERVICE_VERSION, +}; use trusted_server_core::ec::device::DeviceSignals; use trusted_server_core::ec::finalize::ec_finalize_response; use trusted_server_core::ec::kv::KvIdentityGraph; @@ -20,10 +27,13 @@ use trusted_server_core::ec::pull_sync::{ }; use trusted_server_core::ec::registry::PartnerRegistry; use trusted_server_core::error::TrustedServerError; +use trusted_server_core::geo::GeoLookupState; use trusted_server_core::integrations::RequestFilterEffects; use trusted_server_core::platform::PlatformGeo as _; -use trusted_server_core::platform::RuntimeServices; +use trusted_server_core::platform::{RuntimeServices, TimedKvStore}; use trusted_server_core::proxy::{AssetProxyCachePolicy, stream_asset_body}; +use trusted_server_core::publisher::TemplateCacheResponseState; +use trusted_server_core::request_timing::{Phase, RequestTimings, append_server_timing_if_private}; use trusted_server_core::response_privacy::TerminalPrivateResponse; use trusted_server_core::settings::Settings; @@ -111,19 +121,42 @@ fn edgezero_main(mut req: FastlyRequest) { return; } - let config_store = match open_trusted_server_config_store() { - Ok(cs) => cs, - Err(e) => { - log::error!("failed to open config store: {e}"); - FastlyResponse::from_status(fastly::http::StatusCode::INTERNAL_SERVER_ERROR) - .with_body_text_plain("Internal Server Error") - .send_to_client(); - return; - } - }; + let timings = RequestTimings::new(); - let (app, app_state) = TrustedServerApp::build_app_with_state(); + let (config_store, app, app_state) = { + let _appbuild = timings.span(Phase::AppBuild); + let config_store = match open_trusted_server_config_store() { + Ok(cs) => cs, + Err(e) => { + log::error!("failed to open config store: {e}"); + FastlyResponse::from_status(fastly::http::StatusCode::INTERNAL_SERVER_ERROR) + .with_body_text_plain("Internal Server Error") + .send_to_client(); + return; + } + }; + let (app, app_state) = TrustedServerApp::build_app_with_state(); + (config_store, app, app_state) + }; let settings_snapshot = app_state.as_ref().map(|state| Arc::clone(&state.settings)); + let server_timing_enabled = settings_snapshot + .as_deref() + .is_some_and(|settings| settings.observability.server_timing_enabled); + // Both read once here rather than at each `send_edgezero_response` call + // site: if `app_state` failed to build, there is no settings snapshot to + // read them from at all, so every call site would need the same + // degraded-mode fallback. `access_sample_rate` defaults to `0.0` (never + // sampled in) and `publisher_domain` to `"unknown"` in that case. + let access_sample_rate = settings_snapshot + .as_deref() + .map_or(0.0, |settings| settings.tinybird.access_sample_rate); + let access_telemetry_enabled = settings_snapshot + .as_deref() + .is_some_and(|settings| settings.tinybird.enabled && settings.tinybird.access_enabled); + let publisher_domain = settings_snapshot.as_deref().map_or_else( + || "unknown".to_owned(), + |settings| settings.publisher.domain.clone(), + ); // Strip client-spoofable forwarded headers before dispatch. compat::sanitize_fastly_forwarded_headers(&mut req); @@ -138,8 +171,11 @@ fn edgezero_main(mut req: FastlyRequest) { req.set_header("fastly-ssl", "1"); } - // Capture client IP before the request is consumed by dispatch. + // Capture client IP and method before the request is consumed by + // dispatch: nothing else survives to the freeze point in + // `send_edgezero_response`, which only receives the response. let client_ip = req.get_client_ip_addr(); + let request_method = req.get_method_str().to_owned(); // Strip any client-supplied x-ts-tls-* headers before injecting the trusted // values from the Fastly SDK. Must run after sanitize_fastly_forwarded_headers. @@ -171,6 +207,7 @@ fn edgezero_main(mut req: FastlyRequest) { core_req.extensions_mut().insert(config_store); core_req.extensions_mut().insert(device_signals); core_req.extensions_mut().insert(client_info); + core_req.extensions_mut().insert(timings.clone()); match futures::executor::block_on(app.router().oneshot(core_req)) { Ok(response) => response, Err(error) => edge_error_response(error), @@ -189,14 +226,34 @@ fn edgezero_main(mut req: FastlyRequest) { let ec_state = response.extensions_mut().remove::(); let asset_cache_policy = response.extensions_mut().remove::(); let request_filter_effects = response.extensions_mut().remove::(); + // Read rather than pop: the access-telemetry snapshot built later in + // `send_edgezero_response` reads this same extension, so it must still + // be attached to `response` at that point. + let geo_lookup_state = response + .extensions() + .get::() + .cloned() + .unwrap_or(GeoLookupState::NotAttempted); if !take_finalize_sentinel(&mut response) { if let Some(settings) = settings_snapshot.as_deref() { - apply_entry_point_finalize_headers(settings, &mut response, client_ip); + apply_entry_point_finalize_headers( + settings, + &mut response, + client_ip, + &geo_lookup_state, + &timings, + ); } else { match load_settings_from_config_store() { Ok(settings) => { - apply_entry_point_finalize_headers(&settings, &mut response, client_ip); + apply_entry_point_finalize_headers( + &settings, + &mut response, + client_ip, + &geo_lookup_state, + &timings, + ); } Err(e) => { log::warn!("entry-point finalize skipped: failed to reload settings: {e:?}"); @@ -211,10 +268,22 @@ fn edgezero_main(mut req: FastlyRequest) { if let Some(ec_state) = ec_state { if let Some(settings) = settings_snapshot.as_deref() { - match apply_edgezero_ec_finalize(settings, &ec_state, &mut response) { + match apply_edgezero_ec_finalize(settings, &ec_state, &mut response, &timings) { Ok(partner_registry) => { - send_edgezero_response(response, request_filter_effects.as_ref()); + let outcome = send_edgezero_response( + response, + request_filter_effects.as_ref(), + &SendContext { + timings: timings.clone(), + server_timing_enabled, + method: request_method.clone(), + publisher_domain: publisher_domain.clone(), + access_sample_rate, + access_telemetry_enabled, + }, + ); run_edgezero_pull_sync_after_send(settings, &partner_registry, &ec_state); + emit_access_telemetry_after_send(settings, &outcome, &timings); return; } Err(e) => { @@ -226,14 +295,27 @@ fn edgezero_main(mut req: FastlyRequest) { } else { match load_settings_from_config_store() { Ok(settings) => { - match apply_edgezero_ec_finalize(&settings, &ec_state, &mut response) { + match apply_edgezero_ec_finalize(&settings, &ec_state, &mut response, &timings) + { Ok(partner_registry) => { - send_edgezero_response(response, request_filter_effects.as_ref()); + let outcome = send_edgezero_response( + response, + request_filter_effects.as_ref(), + &SendContext { + timings: timings.clone(), + server_timing_enabled, + method: request_method.clone(), + publisher_domain: publisher_domain.clone(), + access_sample_rate, + access_telemetry_enabled, + }, + ); run_edgezero_pull_sync_after_send( &settings, &partner_registry, &ec_state, ); + emit_access_telemetry_after_send(&settings, &outcome, &timings); return; } Err(e) => { @@ -250,7 +332,32 @@ fn edgezero_main(mut req: FastlyRequest) { } } - send_edgezero_response(response, request_filter_effects.as_ref()); + let outcome = send_edgezero_response( + response, + request_filter_effects.as_ref(), + &SendContext { + timings: timings.clone(), + server_timing_enabled, + method: request_method, + publisher_domain, + access_sample_rate, + access_telemetry_enabled, + }, + ); + // The asset/admin/error fallback path: no `EcFinalizeState` (or the ec + // finalize branch above failed), so there is no pull-sync dispatch here + // at all — telemetry is the only post-send step. Reload settings when + // `app_state` never built, matching the fallback used earlier in this + // function for entry-point finalize headers. + match settings_snapshot.as_deref() { + Some(settings) => emit_access_telemetry_after_send(settings, &outcome, &timings), + None => match load_settings_from_config_store() { + Ok(settings) => emit_access_telemetry_after_send(&settings, &outcome, &timings), + Err(e) => { + log::warn!("access telemetry emission skipped: failed to reload settings: {e:?}"); + } + }, + } } fn edge_error_response(error: EdgeError) -> HttpResponse { @@ -278,24 +385,40 @@ fn apply_entry_point_finalize_headers( settings: &Settings, response: &mut HttpResponse, client_ip: Option, + geo_state: &GeoLookupState, + timings: &RequestTimings, ) { - let geo_info = resolve_geo_for_response(response, client_ip, |client_ip| { + let geo_info = resolve_geo_for_response(response, geo_state, client_ip, |client_ip| { + let _span = timings.span(Phase::Geo); FastlyPlatformGeo.lookup(client_ip).unwrap_or_else(|e| { log::warn!("entry-point geo lookup failed: {e}"); None }) }); apply_finalize_headers(settings, geo_info.as_ref(), response); + + // This path runs only when the middleware chain was bypassed (e.g. a + // router-level 404/405 for an unregistered method), so `geo_state` may + // still be `NotAttempted` even after a fresh lookup just ran above. + // Write the resolved outcome back so the access-telemetry snapshot built + // later in `send_edgezero_response` sees what was actually looked up, + // not the stale carried-in state. + let resolved_state = match &geo_info { + Some(info) => GeoLookupState::Resolved(info.clone()), + None => GeoLookupState::Attempted, + }; + response.extensions_mut().insert(resolved_state); } fn apply_edgezero_ec_finalize( settings: &Settings, ec_state: &EcFinalizeState, response: &mut HttpResponse, + timings: &RequestTimings, ) -> Result> { let partner_registry = PartnerRegistry::from_config(&settings.ec.partners)?; let finalize_kv_graph = if ec_state.use_finalize_kv { - maybe_identity_graph(settings) + identity_graph_with_timing(settings, timings) } else { None }; @@ -323,6 +446,253 @@ fn run_edgezero_pull_sync_after_send( } } +/// Builds and emits the access-telemetry row for one delivered response, +/// when access telemetry is enabled and this request is sampled in. +/// +/// Called last at every `send_edgezero_response` call site in +/// [`edgezero_main`] — after `run_edgezero_pull_sync_after_send` on the two +/// EC-finalized paths, and directly after send on the asset/admin/error +/// fallback path, which never builds an [`EcFinalizeState`] or route-scoped +/// `RuntimeServices` at all. The Tinybird transport context is therefore +/// constructed fresh from `settings` here rather than threaded through +/// either of those per-route types, so every response class can emit. +/// +/// Sampled-out requests return silently — that is the expected, high-volume +/// case and not worth a log line. A snapshot carrying a degraded +/// `sample_rate` (see [`should_sample_access_row`]) also returns silently, +/// since it only occurs on an already-degraded path. Every other drop (row +/// build, token load, send, or non-2xx status — all folded into +/// `emit_access_event`'s `Result`) logs exactly one warning naming the +/// reason. +fn emit_access_telemetry_after_send( + settings: &Settings, + outcome: &DeliveryOutcome, + timings: &RequestTimings, +) { + if !settings.tinybird.enabled || !settings.tinybird.access_enabled { + return; + } + + // No snapshot means access telemetry was disabled when the response + // was sent (the flag is read once, before dispatch); nothing to emit. + let Some(snapshot) = &outcome.snapshot else { + return; + }; + + let since_epoch = SystemTime::now() + .duration_since(UNIX_EPOCH) + .unwrap_or_default(); + let epoch_ms = u64::try_from(since_epoch.as_millis()).unwrap_or(u64::MAX); + // Entropy for the sampling decision: the timestamp's nanosecond + // resolution XORed with a per-request value already on hand + // (`outcome.bytes`), so two requests handled in the same instance never + // collide on sampling decisions purely because they read the same + // millisecond. There is no `rand` crate dependency here — see + // `tinybird::sampled_in`. + let entropy_nanos = u64::try_from(since_epoch.as_nanos()).unwrap_or(u64::MAX); + let entropy = entropy_nanos ^ outcome.bytes; + + if !should_sample_access_row( + snapshot.sample_rate, + settings.tinybird.access_sample_rate, + entropy, + ) { + return; + } + + let row = access_event_row(snapshot, &timings.snapshot(), epoch_ms); + let target = tinybird::TinybirdEventsTarget::from_access_config(settings.tinybird.clone()); + let result = futures::executor::block_on(tinybird::emit_access_event( + &platform::FastlyPlatformHttpClient, + &target, + row, + )); + if let Err(error) = result { + log::warn!("access telemetry emission dropped: {error:?}"); + } +} + +/// Whether one response's access-telemetry row should be emitted, combining +/// the degraded-snapshot guard with the sampling roll. +/// +/// `snapshot_sample_rate` is the rate recorded on the [`AccessTelemetrySnapshot`] +/// itself (the value serialized into the row's `sample_rate` column, which +/// the documented volume estimator divides by as `1.0 / sample_rate`). +/// `settings_sample_rate` is the rate used for the sampling decision at +/// call time. The two can diverge: when `app_state` fails to build, +/// [`edgezero_main`] captures a snapshot with `sample_rate` defaulted to +/// `0.0` before any settings ever load, but the two settings-reload +/// emission sites still gate and sample using the *reloaded* settings' +/// (nonzero) rate. Without this guard, such a row could be sampled in and +/// emitted while carrying `sample_rate: 0.0`, corrupting the volume +/// estimator. Dropping these rows is acceptable: they only occur on an +/// already-degraded path, consistent with this pipeline's fail-quiet +/// telemetry policy. Split out of [`emit_access_telemetry_after_send`] so +/// the guard is unit-testable without a network seam. +/// +/// Callers must already have applied the coarse +/// `tinybird.enabled`/`access_enabled` gate. +#[must_use] +fn should_sample_access_row( + snapshot_sample_rate: f64, + settings_sample_rate: f64, + entropy: u64, +) -> bool { + if snapshot_sample_rate <= 0.0 { + return false; + } + + tinybird::sampled_in(settings_sample_rate, entropy) +} + +/// Per-response context threaded into [`send_edgezero_response`] so the +/// function stays at or under seven parameters. +struct SendContext { + /// The request's phase-timing collector. + timings: RequestTimings, + /// Whether `observability.server_timing_enabled` is set. + server_timing_enabled: bool, + /// The request's HTTP method, captured before the request was consumed + /// by dispatch. + method: String, + /// The configured publisher domain. + publisher_domain: String, + /// The configured access-telemetry sample rate. + access_sample_rate: f64, + /// Whether `tinybird.enabled` and `tinybird.access_enabled` were both + /// set when settings were first read. Gates building the + /// [`AccessTelemetrySnapshot`] at all: the snapshot costs env reads and + /// `String` allocations on the pre-send path, which a disabled + /// deployment (the default) should not pay. + access_telemetry_enabled: bool, +} + +/// Outcome of handing a finalized response to the client. +#[allow(dead_code)] +pub(crate) struct DeliveryOutcome { + /// Response body size in bytes. + pub bytes: u64, + /// Whether delivery completed or failed partway. + pub result: DeliveryResult, + /// Access-telemetry dimensions captured for this response at the + /// freeze point. `None` when access telemetry was disabled at snapshot + /// time; the emitter treats that as nothing to send. + pub snapshot: Option, +} + +/// Whether [`send_edgezero_response`] completed delivery or failed partway. +#[derive(Debug, PartialEq, Eq)] +pub(crate) enum DeliveryResult { + /// The response was handed to the client in full. + Complete, + /// Delivery started but did not finish cleanly: some bytes reached the + /// client's transport before a stream error, or the transport could not + /// be closed cleanly after every byte was written. + Partial, + /// Delivery failed before any bytes reached the client. + Error, +} + +/// Thin Fastly-adapter wrapper around +/// [`append_server_timing_if_private`], the freeze point shared with the +/// Axum adapter's terminal timing layer. See that function's doc for the +/// emission rules (always stamps `mark_headers_ready`; appends rather than +/// overwrites; never promotes a response to shared-cacheable). +pub(crate) fn apply_server_timing_header( + response: &mut HttpResponse, + timings: &RequestTimings, + server_timing_enabled: bool, +) { + append_server_timing_if_private(response, timings, server_timing_enabled); +} + +/// A [`Write`](std::io::Write) wrapper that tallies bytes successfully written +/// to the inner writer. +/// +/// Wraps the client transport during a streaming drive so a truncated or +/// failed drive still reports how many bytes actually reached it, instead of +/// the placeholder `0` a failed/aborted drive would otherwise report. +struct CountingWriter { + inner: W, + bytes: u64, +} + +impl CountingWriter { + fn new(inner: W) -> Self { + Self { inner, bytes: 0 } + } + + /// Bytes successfully written to the inner writer so far. + fn bytes(&self) -> u64 { + self.bytes + } + + fn into_inner(self) -> W { + self.inner + } +} + +impl std::io::Write for CountingWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let written = self.inner.write(buf)?; + self.bytes = self.bytes.saturating_add(written as u64); + Ok(written) + } + + fn flush(&mut self) -> std::io::Result<()> { + self.inner.flush() + } +} + +/// Drives a streaming `EdgeZero` body through `output`, tallying bytes written +/// and timing the drive into `timings`. +/// +/// Stamps `resp_bytes` and `request_elapsed` immediately once the drive +/// returns — before the caller does anything transport-specific (finishing +/// the streaming body, logging) — so `request_elapsed` never includes that +/// work. Returns the counting writer (so the caller can recover both the +/// tallied byte count and the wrapped transport) alongside the drive's +/// result. +fn drive_streaming_body( + body: EdgeBody, + output: W, + timings: &RequestTimings, +) -> (CountingWriter, Result<(), Report>) { + let mut counting = CountingWriter::new(output); + let drive_started = Instant::now(); + let result = futures::executor::block_on(stream_asset_body(body, &mut counting)); + timings.record(Phase::Stream, drive_started.elapsed()); + timings.set_resp_bytes(counting.bytes()); + timings.mark_request_elapsed(); + (counting, result) +} + +/// Classifies a completed streaming drive into a [`DeliveryResult`]. +/// +/// A drive that failed after writing at least one byte delivered a truncated +/// response rather than nothing at all, so it is [`DeliveryResult::Partial`], +/// not [`DeliveryResult::Error`]. +fn classify_stream_delivery( + drive_result: &Result<(), Report>, + bytes: u64, +) -> DeliveryResult { + match drive_result { + Ok(()) => DeliveryResult::Complete, + Err(_) if bytes > 0 => DeliveryResult::Partial, + Err(_) => DeliveryResult::Error, + } +} + +/// Stamps `resp_bytes`/`request_elapsed` for an already-materialized body, +/// immediately before it is handed to the Fastly client transport, and +/// returns its byte length. +fn record_buffered_delivery(body: &EdgeBody, timings: &RequestTimings) -> u64 { + let bytes = u64::try_from(body.as_bytes().map(<[u8]>::len).unwrap_or(0)).unwrap_or(u64::MAX); + timings.set_resp_bytes(bytes); + timings.mark_request_elapsed(); + bytes +} + /// Sends a finalized `EdgeZero` response to the client. /// /// Streaming `EdgeZero` bodies commit headers first, then pipe chunks to Fastly's @@ -331,8 +701,24 @@ fn run_edgezero_pull_sync_after_send( fn send_edgezero_response( mut response: HttpResponse, request_filter_effects: Option<&RequestFilterEffects>, -) { + context: &SendContext, +) -> DeliveryOutcome { apply_terminal_response_effects(&mut response, request_filter_effects); + apply_server_timing_header( + &mut response, + &context.timings, + context.server_timing_enabled, + ); + + // Built right after the freeze point and before `into_parts()` + // consumes `response`: nothing else survives to post-send on every + // path (the request was consumed by dispatch, and `EcFinalizeState` + // is absent on asset, admin, and error paths). Skipped entirely when + // access telemetry is disabled, so the default configuration pays no + // env reads or allocations here. + let snapshot = context + .access_telemetry_enabled + .then(|| build_access_telemetry_snapshot(&response, context)); let (parts, body) = response.into_parts(); @@ -342,25 +728,133 @@ fn send_edgezero_response( parts, EdgeBody::empty(), )); - let mut streaming_body = skeleton.stream_to_client(); - match futures::executor::block_on(stream_asset_body(body, &mut streaming_body)) { - Ok(()) => { - if let Err(e) = streaming_body.finish() { + let (counting, drive_result) = + drive_streaming_body(body, skeleton.stream_to_client(), &context.timings); + let bytes = counting.bytes(); + let streaming_body = counting.into_inner(); + // Computed before `drive_result` is matched by value below, since + // the `Err` arm there moves its `Report` out. + let result = classify_stream_delivery(&drive_result, bytes); + match drive_result { + Ok(()) => match streaming_body.finish() { + Ok(()) => DeliveryOutcome { + bytes, + result: DeliveryResult::Complete, + snapshot, + }, + Err(e) => { + // Every byte was handed to the transport (the drive + // above returned Ok), but the transport itself could + // not close cleanly — the client may still see a + // truncated response. log::error!("failed to finish EdgeZero streaming body: {e}"); + DeliveryOutcome { + bytes, + result: DeliveryResult::Partial, + snapshot, + } } - } + }, Err(e) => { log::error!("EdgeZero streaming failed: {e:?}"); drop(streaming_body); + DeliveryOutcome { + bytes, + result, + snapshot, + } } } } once => { + let bytes = record_buffered_delivery(&once, &context.timings); compat::to_fastly_response(HttpResponse::from_parts(parts, once)).send_to_client(); + DeliveryOutcome { + bytes, + result: DeliveryResult::Complete, + snapshot, + } + } + } +} + +/// Builds the [`AccessTelemetrySnapshot`] for `response` at the +/// `Server-Timing` freeze point. +/// +/// Reads route identity, geo country, and template-cache state from typed +/// response extensions rather than the headers those extensions back — +/// operator-configured response headers can override a managed header, so +/// reading a header here could silently drift from what actually happened. +/// Falls back to `"unknown"`/[`RouteClass::Other`] sentinels when an +/// extension was never attached (router-generated, asset, and other +/// responses that never passed through a `RouteMetadata`-attaching +/// wrapper). +fn build_access_telemetry_snapshot( + response: &HttpResponse, + context: &SendContext, +) -> AccessTelemetrySnapshot { + let (route_class, route_template) = match response.extensions().get::() { + Some(metadata) => (metadata.route_class, metadata.route_template.clone()), + None => (RouteClass::Other, "unknown".to_owned()), + }; + + let country = match response.extensions().get::() { + Some(GeoLookupState::Resolved(info)) => info.country.clone(), + Some(GeoLookupState::Attempted | GeoLookupState::NotAttempted) | None => { + "unknown".to_owned() } + }; + + let template_cache_state = response + .extensions() + .get::() + .map_or_else(|| "unknown".to_owned(), |state| state.as_str().to_owned()); + + let body_mode = if matches!(response.body(), EdgeBody::Stream(_)) { + "streamed" + } else { + "buffered" + }; + + AccessTelemetrySnapshot { + method: context.method.clone(), + status: response.status().as_u16(), + route_class, + route_template, + publisher_domain: context.publisher_domain.clone(), + env: resolve_env_dimension(), + service_id: env_var_or_unknown(ENV_FASTLY_SERVICE_ID), + pop: env_var_or_unknown(ENV_FASTLY_POP), + ts_version: env_var_or_unknown(ENV_FASTLY_SERVICE_VERSION), + country, + template_cache_state, + body_mode, + sample_rate: context.access_sample_rate, } } +/// Derives the `env` access-telemetry dimension from the same +/// `FASTLY_IS_STAGING` input that drives the `x-ts-env` response header +/// (see [`apply_finalize_headers`]), never from [`Settings`] — `Settings` +/// has no environment field and does not gain one for this. +/// +/// `"unknown"` covers contexts where the variable is entirely absent (for +/// example native unit tests run outside Fastly Compute); on the Fastly +/// platform the variable is always present, as either `"1"` or not. +fn resolve_env_dimension() -> String { + match std::env::var(ENV_FASTLY_IS_STAGING) { + Ok(value) if value == "1" => "staging".to_owned(), + Ok(_) => "production".to_owned(), + Err(_) => "unknown".to_owned(), + } +} + +/// Reads a Fastly-provided environment variable, defaulting to `"unknown"` +/// when unset. +fn env_var_or_unknown(name: &str) -> String { + std::env::var(name).unwrap_or_else(|_| "unknown".to_owned()) +} + /// Apply every late response mutation, then restore privacy invariants before headers commit. fn apply_terminal_response_effects( response: &mut HttpResponse, @@ -432,12 +926,21 @@ fn build_ja4_debug_response(req: &FastlyRequest) -> FastlyResponse { .with_body(body) } -pub(crate) fn maybe_identity_graph(settings: &Settings) -> Option { - settings - .ec - .ec_store - .as_ref() - .map(|store_name| KvIdentityGraph::new(FastlyEcKvStore::new(store_name))) +/// Constructs a `KvIdentityGraph` wrapped in the [`Phase::EcKv`] timing +/// decorator, for request-path callers with a `RequestTimings` handle. +/// +/// Returns `None` when `ec.ec_store` is not configured, matching +/// [`require_identity_graph_with_timing`]'s contract on every other axis. +pub(crate) fn identity_graph_with_timing( + settings: &Settings, + timings: &RequestTimings, +) -> Option { + settings.ec.ec_store.as_ref().map(|store_name| { + KvIdentityGraph::new(TimedKvStore::new( + FastlyEcKvStore::new(store_name), + timings.clone(), + )) + }) } fn run_pull_sync_after_send( @@ -460,6 +963,12 @@ fn run_pull_sync_after_send( /// Constructs a `KvIdentityGraph` from settings, or returns an error if the /// `ec_store` config is not set. +/// +/// Deliberately untimed: pull-sync (this function's only caller) runs after +/// `send_edgezero_response`'s Server-Timing freeze point, so a decorated +/// store here would record into a handle nothing ever renders. +/// Request-path callers with a `RequestTimings` handle use +/// [`require_identity_graph_with_timing`] instead. pub(crate) fn require_identity_graph( settings: &Settings, ) -> Result> { @@ -472,6 +981,27 @@ pub(crate) fn require_identity_graph( Ok(KvIdentityGraph::new(FastlyEcKvStore::new(store_name))) } +/// Constructs a `KvIdentityGraph` wrapped in the [`Phase::EcKv`] timing +/// decorator, or returns an error if the `ec_store` config is not set. +/// +/// Request-path sibling of [`require_identity_graph`], which pull-sync uses +/// unwrapped because pull-sync runs after the Server-Timing freeze point. +pub(crate) fn require_identity_graph_with_timing( + settings: &Settings, + timings: &RequestTimings, +) -> Result> { + let store_name = settings.ec.ec_store.as_deref().ok_or_else(|| { + Report::new(TrustedServerError::KvStore { + store_name: "ec.ec_store".to_owned(), + message: "ec.ec_store is not configured".to_owned(), + }) + })?; + Ok(KvIdentityGraph::new(TimedKvStore::new( + FastlyEcKvStore::new(store_name), + timings.clone(), + ))) +} + /// Extracts a named cookie value from the request's `Cookie` header. pub(crate) fn extract_cookie_value(req: &HttpRequest, name: &str) -> Option { let cookie_header = req.headers().get("cookie").and_then(|v| v.to_str().ok())?; @@ -501,11 +1031,15 @@ pub(crate) fn derive_device_signals(req: &FastlyRequest) -> DeviceSignals { #[cfg(test)] mod tests { use super::*; + use base64::Engine as _; use edgezero_core::body::Body as EdgeBody; use edgezero_core::http::HeaderValue; use edgezero_core::http::response_builder; use fastly::mime; + use std::sync::Mutex; + use std::time::Duration; use trusted_server_core::integrations::HeaderMutation; + use trusted_server_core::request_timing::AuctionWaitPlacement; fn test_settings() -> Settings { Settings::from_toml( @@ -533,6 +1067,26 @@ mod tests { .expect("should parse test settings") } + /// A minimal [`AccessTelemetrySnapshot`] fixture for tests that only + /// need a `DeliveryOutcome` to exist, not its telemetry content. + fn sample_access_snapshot() -> AccessTelemetrySnapshot { + AccessTelemetrySnapshot { + method: "GET".to_owned(), + status: 200, + route_class: RouteClass::Other, + route_template: "/other/*".to_owned(), + publisher_domain: "unknown".to_owned(), + env: "unknown".to_owned(), + service_id: "unknown".to_owned(), + pop: "unknown".to_owned(), + ts_version: "unknown".to_owned(), + country: "unknown".to_owned(), + template_cache_state: "unknown".to_owned(), + body_mode: "buffered", + sample_rate: 0.0, + } + } + #[test] fn health_response_short_circuits_get_health() { let req = FastlyRequest::get("https://example.com/health"); @@ -768,9 +1322,10 @@ mod tests { .body(EdgeBody::empty()) .expect("should build response"); - let geo_info = resolve_geo_for_response(&response, None, |_| { - panic!("should skip entry-point geo lookup for 401 responses"); - }); + let geo_info = + resolve_geo_for_response(&response, &GeoLookupState::NotAttempted, None, |_| { + panic!("should skip entry-point geo lookup for 401 responses"); + }); apply_finalize_headers(&settings, geo_info.as_ref(), &mut response); assert_eq!( @@ -836,4 +1391,540 @@ mod tests { "should include sec-ch-ua-platform fallback" ); } + + fn ec_finalize_settings() -> Settings { + Settings::from_toml( + r#" + [[handlers]] + path = "^/_ts/admin" + username = "admin" + password = "admin-pass" + + [publisher] + domain = "test-publisher.com" + cookie_domain = ".test-publisher.com" + origin_url = "https://origin.test-publisher.com" + proxy_secret = "unit-test-proxy-secret" + + [ec] + passphrase = "test-secret-key-32-bytes-minimum" + ec_store = "ec_identity_store" + + [[ec.partners]] + name = "Example Partner" + source_domain = "example.com" + api_token = "test-vendor-token-32-bytes-minimum" + + [request_signing] + enabled = false + config_store_id = "test-config-store-id" + secret_store_id = "test-secret-store-id" + "#, + ) + .expect("should parse EC finalize test settings") + } + + /// Minimal `RuntimeServices` for `EcFinalizeState.services`. Real + /// `FastlyPlatform*` handles are used as inert placeholders: EC + /// finalization never calls through them, it only satisfies the field. + fn inert_runtime_services() -> RuntimeServices { + RuntimeServices::builder() + .config_store(Arc::new(crate::platform::FastlyPlatformConfigStore)) + .secret_store(Arc::new(crate::platform::FastlyPlatformSecretStore)) + .kv_store(Arc::new(edgezero_core::key_value_store::NoopKvStore) + as Arc) + .backend(Arc::new(crate::platform::FastlyPlatformBackend)) + .http_client(Arc::new(crate::platform::FastlyPlatformHttpClient)) + .geo(Arc::new(crate::platform::FastlyPlatformGeo)) + .client_info(trusted_server_core::platform::ClientInfo::default()) + .build() + } + + #[test] + fn ec_finalize_kv_lands_before_freeze() { + // A pre-seeded EC entry (see fastly.toml's ec_identity_store fixture) + // for a returning user carrying an eids cookie that matches the + // configured partner. This drives ec_finalize_response into + // ingest_eid_cookies, which reads and writes the KV identity graph. + let settings = ec_finalize_settings(); + let ec_id = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.test01"; + let eids = serde_json::json!([{ + "source": "example.com", + "uids": [{ "id": "example-uid", "atype": 1 }] + }]); + let eids_cookie = base64::engine::general_purpose::STANDARD.encode(eids.to_string()); + let request = edgezero_core::http::request_builder() + .method(fastly::http::Method::GET) + .uri("https://test-publisher.com/article") + .header("cookie", format!("ts-ec={ec_id}; ts-eids={eids_cookie}")) + .body(EdgeBody::empty()) + .expect("should build EC finalize test request"); + + let services = inert_runtime_services(); + let geo_info = trusted_server_core::platform::GeoInfo { + city: String::new(), + country: "US".to_owned(), + continent: "NorthAmerica".to_owned(), + latitude: 0.0, + longitude: 0.0, + metro_code: 0, + region: None, + asn: None, + }; + let ec_context = trusted_server_core::ec::EcContext::read_from_request_with_geo( + &settings, + &request, + &services, + Some(&geo_info), + ) + .expect("should read EC context from a non-regulated request"); + assert!( + ec_context.ec_was_present(), + "the pre-seeded ts-ec cookie should be recognized" + ); + + let ec_state = EcFinalizeState { + ec_context, + use_finalize_kv: true, + eids_cookie: Some(eids_cookie), + sharedid_cookie: None, + is_real_browser: true, + services, + }; + let mut response = response_builder() + .header("cache-control", "private, no-store") + .body(EdgeBody::empty()) + .expect("should build EC finalize response fixture"); + let timings = RequestTimings::new(); + + // Mirrors edgezero_main's ordering: EC finalize runs, then the freeze + // point (apply_server_timing_header, called just before + // response.into_parts() inside send_edgezero_response) renders the + // header. Calling both directly exercises exactly this order without + // requiring a live Fastly client connection. + apply_edgezero_ec_finalize(&settings, &ec_state, &mut response, &timings) + .expect("should finalize EC response"); + apply_server_timing_header(&mut response, &timings, true); + + let header = response + .headers() + .get("server-timing") + .and_then(|v| v.to_str().ok()) + .expect("should emit a Server-Timing header"); + assert!( + header.contains("ts-kv"), + "the freeze point must run after EC finalization recorded KV time: {header}" + ); + } + + #[test] + fn delivery_outcome_reports_bytes_and_request_elapsed_set() { + let timings = RequestTimings::new(); + let body = EdgeBody::stream(futures::stream::iter(vec![ + bytes::Bytes::from_static(b"hello "), + bytes::Bytes::from_static(b"world"), + ])); + + let (counting, drive_result) = drive_streaming_body(body, Vec::new(), &timings); + drive_result.expect("streaming a well-formed body should not fail"); + let bytes = counting.bytes(); + let outcome = DeliveryOutcome { + bytes, + result: DeliveryResult::Complete, + snapshot: Some(sample_access_snapshot()), + }; + + assert_eq!( + counting.into_inner(), + b"hello world", + "should write every byte to the underlying transport" + ); + assert_eq!( + outcome.bytes, + "hello world".len() as u64, + "DeliveryOutcome.bytes should equal the streamed body length" + ); + + let snapshot = timings.snapshot(); + assert_eq!( + snapshot.resp_bytes, + Some("hello world".len() as u64), + "should stamp resp_bytes to the tallied byte count" + ); + assert!( + snapshot.request_elapsed_ms.is_some(), + "should stamp request_elapsed once the drive returns" + ); + } + + #[test] + fn buffered_delivery_stamps_bytes_and_request_elapsed() { + let timings = RequestTimings::new(); + let body = EdgeBody::from(b"a buffered body".to_vec()); + + let bytes = record_buffered_delivery(&body, &timings); + + assert_eq!( + bytes, + "a buffered body".len() as u64, + "should report the buffered body length" + ); + let snapshot = timings.snapshot(); + assert_eq!( + snapshot.resp_bytes, + Some("a buffered body".len() as u64), + "should stamp resp_bytes for the buffered path too" + ); + assert!( + snapshot.request_elapsed_ms.is_some(), + "should stamp request_elapsed for the buffered path too" + ); + } + + fn send_context_fixture() -> SendContext { + SendContext { + timings: RequestTimings::new(), + server_timing_enabled: false, + method: "GET".to_owned(), + publisher_domain: "test-publisher.com".to_owned(), + access_sample_rate: 0.25, + access_telemetry_enabled: true, + } + } + + #[test] + fn access_snapshot_defaults_when_no_extensions_are_attached() { + // Router-generated 404/405 responses and other paths that never pass + // through a RouteMetadata-attaching wrapper must still produce a + // usable snapshot: RouteClass::Other and "unknown" sentinels, never + // a missing/panicking build. + let response = response_builder() + .status(404) + .body(EdgeBody::empty()) + .expect("should build response"); + let context = send_context_fixture(); + + let snapshot = build_access_telemetry_snapshot(&response, &context); + + assert_eq!(snapshot.status, 404); + assert_eq!(snapshot.method, "GET"); + assert!(matches!(snapshot.route_class, RouteClass::Other)); + assert_eq!(snapshot.route_template, "unknown"); + assert_eq!(snapshot.country, "unknown"); + assert_eq!(snapshot.template_cache_state, "unknown"); + assert_eq!(snapshot.body_mode, "buffered"); + assert_eq!(snapshot.publisher_domain, "test-publisher.com"); + assert_eq!(snapshot.sample_rate, 0.25); + } + + #[test] + fn access_snapshot_reads_route_geo_and_template_cache_extensions() { + let mut response = response_builder() + .status(200) + .body(EdgeBody::empty()) + .expect("should build response"); + response.extensions_mut().insert(RouteMetadata { + route_class: RouteClass::AuctionApi, + route_template: "/auction".to_owned(), + }); + response.extensions_mut().insert(GeoLookupState::Resolved( + trusted_server_core::platform::GeoInfo { + city: String::new(), + country: "US".to_owned(), + continent: "NorthAmerica".to_owned(), + latitude: 0.0, + longitude: 0.0, + metro_code: 0, + region: None, + asn: None, + }, + )); + response + .extensions_mut() + .insert(TemplateCacheResponseState::Hit); + let context = send_context_fixture(); + + let snapshot = build_access_telemetry_snapshot(&response, &context); + + assert!(matches!(snapshot.route_class, RouteClass::AuctionApi)); + assert_eq!(snapshot.route_template, "/auction"); + assert_eq!(snapshot.country, "US"); + assert_eq!(snapshot.template_cache_state, "hit"); + } + + #[test] + fn access_snapshot_treats_attempted_geo_lookup_as_unknown_country() { + let mut response = response_builder() + .status(200) + .body(EdgeBody::empty()) + .expect("should build response"); + response.extensions_mut().insert(GeoLookupState::Attempted); + let context = send_context_fixture(); + + let snapshot = build_access_telemetry_snapshot(&response, &context); + + assert_eq!( + snapshot.country, "unknown", + "an attempted-but-unresolved lookup must not surface a stale country" + ); + } + + #[test] + fn access_snapshot_body_mode_reflects_the_response_body_variant() { + let streamed = response_builder() + .status(200) + .body(EdgeBody::stream(futures::stream::empty())) + .expect("should build streaming response"); + let buffered = response_builder() + .status(200) + .body(EdgeBody::from(b"hi".to_vec())) + .expect("should build buffered response"); + let context = send_context_fixture(); + + assert_eq!( + build_access_telemetry_snapshot(&streamed, &context).body_mode, + "streamed" + ); + assert_eq!( + build_access_telemetry_snapshot(&buffered, &context).body_mode, + "buffered" + ); + } + + #[test] + fn stream_drive_records_stream_ms_covering_the_in_stream_auction_wait() { + // A streaming seam wait (Task 6, publisher.rs) records into the same + // `RequestTimings` handle the adapter drives with. `Phase::Stream` + // wraps the entire drive, so it must cover — and therefore be at + // least as large as — any `AuctionWait` recorded while the body was + // being polled. + let timings = RequestTimings::new(); + let wait_timings = timings.clone(); + let stream = futures::stream::once(async move { + let waited = Duration::from_millis(5); + std::thread::sleep(waited); + wait_timings.record_auction_wait(AuctionWaitPlacement::InStream, waited); + bytes::Bytes::from_static(b"") + }); + let body = EdgeBody::stream(stream); + + let (_counting, drive_result) = drive_streaming_body(body, Vec::new(), &timings); + drive_result.expect("streaming a well-formed body should not fail"); + + let snapshot = timings.snapshot(); + assert_eq!( + snapshot.auction_wait_placement, + Some(AuctionWaitPlacement::InStream), + "should preserve the placement recorded from inside the polled body" + ); + let auction_wait_ms = snapshot + .auction_wait_ms + .expect("should record the auction wait"); + let stream_ms = snapshot.stream_ms.expect("should record the stream drive"); + assert!( + stream_ms >= auction_wait_ms, + "the drive's Phase::Stream span must cover the in-stream auction wait: \ + stream_ms={stream_ms} auction_wait_ms={auction_wait_ms}" + ); + } + + #[test] + fn classify_stream_delivery_treats_bytes_written_before_an_error_as_partial() { + let err = Report::new(TrustedServerError::Proxy { + message: "boom".to_string(), + }); + assert_eq!( + classify_stream_delivery(&Err(err), 42), + DeliveryResult::Partial, + "bytes already on the wire before a stream error is a truncated delivery" + ); + } + + #[test] + fn classify_stream_delivery_treats_an_error_with_no_bytes_as_error() { + let err = Report::new(TrustedServerError::Proxy { + message: "boom".to_string(), + }); + assert_eq!( + classify_stream_delivery(&Err(err), 0), + DeliveryResult::Error, + "a failure before any byte reached the client is a clean failure, not a truncation" + ); + } + + #[test] + fn classify_stream_delivery_treats_ok_as_complete() { + assert_eq!( + classify_stream_delivery(&Ok(()), 123), + DeliveryResult::Complete + ); + } + + /// Records `"telemetry"` into a shared order log instead of sending a + /// real request, standing in for the adapter's platform HTTP client in + /// [`post_send_order_is_elapsed_then_pull_sync_then_telemetry`]. + struct OrderingHttpClient { + log: Arc>>, + } + + #[async_trait::async_trait(?Send)] + impl trusted_server_core::platform::PlatformHttpClient for OrderingHttpClient { + async fn send( + &self, + _request: trusted_server_core::platform::PlatformHttpRequest, + ) -> Result< + trusted_server_core::platform::PlatformResponse, + Report, + > { + self.log + .lock() + .expect("should lock order log") + .push("telemetry"); + let response = response_builder() + .status(edgezero_core::http::StatusCode::ACCEPTED) + .body(EdgeBody::empty()) + .expect("should build ordering test response"); + Ok(trusted_server_core::platform::PlatformResponse::new( + response, + )) + } + + async fn send_async( + &self, + _request: trusted_server_core::platform::PlatformHttpRequest, + ) -> Result< + trusted_server_core::platform::PlatformPendingRequest, + Report, + > { + Err(Report::new( + trusted_server_core::platform::PlatformError::Unsupported, + )) + } + + async fn select( + &self, + _pending_requests: Vec, + ) -> Result< + trusted_server_core::platform::PlatformSelectResult, + Report, + > { + Err(Report::new( + trusted_server_core::platform::PlatformError::Unsupported, + )) + } + } + + #[test] + fn post_send_order_is_elapsed_then_pull_sync_then_telemetry() { + // `edgezero_main` cannot be driven directly in a unit test (it + // consumes a live `fastly::Request::from_client()`), and + // `run_edgezero_pull_sync_after_send` has no injectable seam of its + // own — it dispatches through the real identity-graph pull-sync + // path, which needs a configured EC KV store, partner registry, and + // rate limiter wired together. This test instead exercises the two + // REAL functions `edgezero_main` calls that DO have a testable seam + // — `send_edgezero_response` (which stamps `request_elapsed` before + // returning, per Task 6/7) and `tinybird::emit_access_event` (the + // telemetry send added by this task) — around an instrumented + // stand-in for the pull-sync dispatch call, in the exact order + // `edgezero_main` places them. + // + // This proves the elapsed-before-telemetry leg from real production + // code (the assertion below reads the real `timings` snapshot + // between the two calls). The pull-sync-before-telemetry leg is a + // source-order invariant in `edgezero_main`'s three call sites + // (verified by code review, not by this test) because + // `run_edgezero_pull_sync_after_send` itself has no seam to + // instrument — see task-8-report.md for this residual. + let log: Arc>> = Arc::new(Mutex::new(Vec::new())); + let timings = RequestTimings::new(); + let response = response_builder() + .body(EdgeBody::from("ok")) + .expect("should build response"); + + let outcome = send_edgezero_response( + response, + None, + &SendContext { + timings: timings.clone(), + server_timing_enabled: false, + method: "GET".to_owned(), + publisher_domain: "test-publisher.com".to_owned(), + access_sample_rate: 1.0, + access_telemetry_enabled: true, + }, + ); + assert!( + timings.snapshot().request_elapsed_ms.is_some(), + "request_elapsed should already be stamped before pull-sync/telemetry run" + ); + + // Stand-in for `run_edgezero_pull_sync_after_send`, which has no + // injectable seam (see the test doc comment above). + log.lock().expect("should lock order log").push("pull_sync"); + + let http_client = OrderingHttpClient { + log: Arc::clone(&log), + }; + let target = tinybird::TinybirdEventsTarget::from_access_config( + trusted_server_core::settings::TinybirdSettings { + api_host: "api.us-east.aws.tinybird.co".to_owned(), + ..trusted_server_core::settings::TinybirdSettings::default() + }, + ); + let snapshot = outcome + .snapshot + .as_ref() + .expect("should build a snapshot when access telemetry is enabled"); + let row = access_event_row(snapshot, &timings.snapshot(), 0); + + futures::executor::block_on(tinybird::emit_access_event(&http_client, &target, row)) + .expect("should send access telemetry"); + + assert_eq!( + *log.lock().expect("should lock order log"), + vec!["pull_sync", "telemetry"], + "pull-sync must dispatch before telemetry emits" + ); + } + + #[test] + fn should_sample_access_row_rejects_a_degraded_zero_sample_rate() { + // A snapshot captured on the app-state-build-failure fallback path + // carries `sample_rate: 0.0`. Even when the reloaded settings' rate + // would sample every request in (1.0), the row must not emit — + // otherwise it would claim `sample_rate: 0.0` and corrupt the + // `sum(1.0 / sample_rate)` volume estimator. + assert!( + !should_sample_access_row(0.0, 1.0, 0), + "a snapshot with sample_rate 0.0 must never emit, regardless of entropy or settings' rate" + ); + assert!( + !should_sample_access_row(0.0, 1.0, u64::MAX), + "the degraded-rate guard must not depend on the entropy value" + ); + } + + #[test] + fn should_sample_access_row_rejects_a_negative_sample_rate() { + assert!( + !should_sample_access_row(-1.0, 1.0, 0), + "a negative snapshot sample_rate is equally degraded and must not emit" + ); + } + + #[test] + fn should_sample_access_row_defers_to_the_settings_sampling_roll_when_not_degraded() { + // With a healthy (nonzero) snapshot sample_rate, the outcome should + // match `tinybird::sampled_in` exactly, since that is the only + // remaining decision. + assert!( + should_sample_access_row(0.25, 1.0, 0), + "a settings rate of 1.0 always samples in, independent of entropy" + ); + assert!( + !should_sample_access_row(0.25, 0.0, 0), + "a settings rate of 0.0 always samples out, independent of the snapshot's rate" + ); + } } diff --git a/crates/trusted-server-adapter-fastly/src/middleware.rs b/crates/trusted-server-adapter-fastly/src/middleware.rs index 18f309c68..ae1efe7c3 100644 --- a/crates/trusted-server-adapter-fastly/src/middleware.rs +++ b/crates/trusted-server-adapter-fastly/src/middleware.rs @@ -24,8 +24,9 @@ use trusted_server_core::constants::{ ENV_FASTLY_IS_STAGING, ENV_FASTLY_SERVICE_VERSION, HEADER_X_GEO_INFO_AVAILABLE, HEADER_X_TS_ENV, HEADER_X_TS_VERSION, }; -use trusted_server_core::geo::GeoInfo; +use trusted_server_core::geo::{GeoInfo, GeoLookupState}; use trusted_server_core::platform::PlatformGeo; +use trusted_server_core::request_timing::{Phase, RequestTimings}; use trusted_server_core::settings::Settings; pub(crate) const HEADER_X_TS_FINALIZED: &str = "x-ts-finalized"; @@ -68,6 +69,12 @@ impl FinalizeResponseMiddleware { impl Middleware for FinalizeResponseMiddleware { async fn handle(&self, ctx: RequestContext, next: Next<'_>) -> Result { let client_ip = FastlyRequestContext::get(ctx.request()).and_then(|c| c.client_ip); + let timings = ctx + .request() + .extensions() + .get::() + .cloned() + .unwrap_or_default(); let mut response = match next.run(ctx).await { Ok(r) => r, @@ -77,13 +84,31 @@ impl Middleware for FinalizeResponseMiddleware { } }; - let geo_info = resolve_geo_for_response(&response, client_ip, |ip| { + let carried = response + .extensions() + .get::() + .cloned() + .unwrap_or(GeoLookupState::NotAttempted); + let geo_info = resolve_geo_for_response(&response, &carried, client_ip, |ip| { + let _span = timings.span(Phase::Geo); self.geo.lookup(ip).unwrap_or_else(|e| { log::warn!("geo lookup failed: {e}"); None }) }); + // Write the resolved outcome back so a downstream access-telemetry + // snapshot (built from response extensions after finalize) sees + // what was actually looked up here rather than the stale carried-in + // state — mirrors the entry-point finalize site in `main.rs` + // (`apply_entry_point_finalize_headers`), which writes back for the + // same reason. + let resolved_state = match &geo_info { + Some(geo) => GeoLookupState::Resolved(geo.clone()), + None => GeoLookupState::Attempted, + }; + response.extensions_mut().insert(resolved_state); + apply_finalize_headers(&self.settings, geo_info.as_ref(), &mut response); response .headers_mut() @@ -142,14 +167,20 @@ impl Middleware for AuthMiddleware { // Shared geo resolution helper // --------------------------------------------------------------------------- -/// Resolves geo for a response, skipping the lookup for 401 responses. +/// Resolves geo for a response, skipping the lookup for 401 responses and +/// reusing a request-phase lookup when one was already carried. /// -/// Returns `None` for authentication rejections (401) without calling `lookup_geo` -/// to avoid unnecessary work and exposing geo data to unauthenticated callers. -/// All other responses call `lookup_geo` and return its result. +/// Returns `None` for authentication rejections (401) without consulting +/// `carried` or calling `lookup_geo`, to avoid unnecessary work and exposing +/// geo data to unauthenticated callers. Otherwise dispatches on `carried`: +/// a [`GeoLookupState::Resolved`] value is reused as-is, a +/// [`GeoLookupState::Attempted`] value is treated as no geo info without +/// retrying the lookup, and [`GeoLookupState::NotAttempted`] falls back to +/// calling `lookup_geo`. /// /// Used by both [`FinalizeResponseMiddleware`] and the entry-point finalization -/// in `main.rs` so the 401-skip rule is defined in one place. +/// in `main.rs` so the 401-skip rule and the dedupe rule are each defined in +/// one place. /// /// # Parity note /// @@ -161,6 +192,7 @@ impl Middleware for AuthMiddleware { /// server or the upstream origin. pub(crate) fn resolve_geo_for_response( response: &Response, + carried: &GeoLookupState, client_ip: Option, lookup_geo: F, ) -> Option @@ -168,9 +200,12 @@ where F: FnOnce(Option) -> Option, { if response.status() == StatusCode::UNAUTHORIZED { - None - } else { - lookup_geo(client_ip) + return None; + } + match carried { + GeoLookupState::Resolved(geo) => Some(geo.clone()), + GeoLookupState::Attempted => None, + GeoLookupState::NotAttempted => lookup_geo(client_ip), } } @@ -277,6 +312,19 @@ mod tests { RequestContext::new(req, PathParams::new(HashMap::new())) } + fn sample_geo_info() -> GeoInfo { + GeoInfo { + city: "Testville".to_string(), + country: "US".to_string(), + continent: "NorthAmerica".to_string(), + latitude: 0.0, + longitude: 0.0, + metro_code: 0, + region: None, + asn: None, + } + } + struct FixedGeo(Option); impl PlatformGeo for FixedGeo { @@ -558,6 +606,67 @@ mod tests { ); } + #[test] + fn finalize_handle_writes_back_resolved_geo_state_after_fallback_lookup() { + // The request phase never attempted a geo lookup (no GeoLookupState + // extension on the handler's response), so the middleware resolves + // one via the fallback closure. That resolved outcome must be + // written back into response extensions -- mirroring + // apply_entry_point_finalize_headers in main.rs -- so a downstream + // access-telemetry snapshot sees the freshly resolved country + // instead of a stale/missing GeoLookupState. + let settings = settings_with_response_headers(vec![]); + let middleware = FinalizeResponseMiddleware::new( + Arc::new(settings), + Arc::new(FixedGeo(Some(sample_geo_info()))), + ); + let handler = + Arc::new( + |_ctx: RequestContext| async move { Ok::(empty_response()) }, + ); + + let response = block_on(middleware.handle(empty_ctx(), Next::new(&[], &*handler))) + .expect("should succeed"); + + match response.extensions().get::() { + Some(GeoLookupState::Resolved(info)) => { + assert_eq!( + info.country, "US", + "should carry the fallback-resolved geo info" + ); + } + other => { + panic!("expected GeoLookupState::Resolved after a fallback lookup, got {other:?}") + } + } + } + + #[test] + fn finalize_handle_writes_back_attempted_geo_state_when_fallback_finds_nothing() { + // The fallback lookup ran but resolved no geo info. The middleware + // must still record that the lookup was attempted, so a later + // consumer of the extension does not mistake this for + // GeoLookupState::NotAttempted and retry the lookup. + let settings = settings_with_response_headers(vec![]); + let middleware = + FinalizeResponseMiddleware::new(Arc::new(settings), Arc::new(FixedGeo(None))); + let handler = + Arc::new( + |_ctx: RequestContext| async move { Ok::(empty_response()) }, + ); + + let response = block_on(middleware.handle(empty_ctx(), Next::new(&[], &*handler))) + .expect("should succeed"); + + assert!( + matches!( + response.extensions().get::(), + Some(GeoLookupState::Attempted) + ), + "should write back Attempted when the fallback lookup finds no geo info" + ); + } + #[test] fn finalize_handle_marks_response_as_finalized() { let settings = settings_with_response_headers(vec![]); @@ -639,6 +748,30 @@ mod tests { ); } + #[test] + #[allow(clippy::panic)] + fn geo_lookup_skipped_for_unauthorized_responses() { + // The 401 short-circuit in resolve_geo_for_response must win + // regardless of what state the request phase carried in, and must + // never invoke the fallback lookup closure. + let mut response = empty_response(); + *response.status_mut() = StatusCode::UNAUTHORIZED; + + for carried in [ + GeoLookupState::NotAttempted, + GeoLookupState::Attempted, + GeoLookupState::Resolved(sample_geo_info()), + ] { + let geo_info = resolve_geo_for_response(&response, &carried, None, |_| { + panic!("401 responses must never trigger a geo lookup"); + }); + assert!( + geo_info.is_none(), + "401 responses should never resolve geo info, regardless of carried state" + ); + } + } + // --------------------------------------------------------------------------- // AuthMiddleware::handle tests // --------------------------------------------------------------------------- diff --git a/crates/trusted-server-adapter-fastly/src/tinybird.rs b/crates/trusted-server-adapter-fastly/src/tinybird.rs index f2df61744..1158ada68 100644 --- a/crates/trusted-server-adapter-fastly/src/tinybird.rs +++ b/crates/trusted-server-adapter-fastly/src/tinybird.rs @@ -11,10 +11,13 @@ use trusted_server_core::auction::telemetry::{ }; use trusted_server_core::error::TrustedServerError; use trusted_server_core::platform::{ - PlatformBackendSpec, PlatformHttpRequest, RuntimeServices, StoreName, + PlatformBackend as _, PlatformBackendSpec, PlatformHttpClient, PlatformHttpRequest, + PlatformSecretStore as _, RuntimeServices, StoreName, }; use trusted_server_core::settings::{Settings, TinybirdSettings}; +use crate::platform::{FastlyPlatformBackend, FastlyPlatformSecretStore}; + const TINYBIRD_EVENTS_PATH: &str = "/v0/events"; const TINYBIRD_NDJSON_CONTENT_TYPE: &str = "application/x-ndjson"; const TINYBIRD_FIRST_BYTE_TIMEOUT: Duration = Duration::from_secs(2); @@ -22,9 +25,14 @@ const TINYBIRD_BETWEEN_BYTES_TIMEOUT: Duration = Duration::from_secs(2); const TINYBIRD_MAX_ROWS_PER_AUCTION_BATCH: usize = 512; /// Build the configured auction telemetry sink. +/// +/// Auction emission requires both the Tinybird master toggle +/// (`tinybird.enabled`) and the auction-specific toggle +/// (`tinybird.auction_enabled`), so access-log telemetry can be enabled +/// independently without also emitting auction events. #[must_use] pub(crate) fn auction_sink_from_settings(settings: &Settings) -> Arc { - if settings.tinybird.enabled { + if settings.tinybird.enabled && settings.tinybird.auction_enabled { Arc::new(FastlyTinybirdAuctionTelemetrySink::new( settings.tinybird.clone(), )) @@ -40,7 +48,7 @@ struct FastlyTinybirdAuctionTelemetrySink { } #[derive(Debug, Clone)] -struct TinybirdEventsTarget { +pub(crate) struct TinybirdEventsTarget { api_host: String, dataset: String, secret_store: StoreName, @@ -64,6 +72,27 @@ impl TinybirdEventsTarget { max_body_bytes: config.max_body_bytes, } } + + /// Builds the Events API target for the access-log datasource. + /// + /// Shares [`from_config`](Self::from_config)'s host/secret-store/ + /// body-size-limit derivation, but points at `access_dataset` and + /// `access_token_secret` instead of the auction pair, so access-log + /// emission never shares a datasource or token with auction telemetry + /// even though both configs come from the same [`TinybirdSettings`]. + pub(crate) fn from_access_config(config: TinybirdSettings) -> Self { + let uri = tinybird_events_uri(&config.api_host, &config.access_dataset); + let backend_spec = tinybird_backend_spec(&config.api_host); + Self { + api_host: config.api_host, + dataset: config.access_dataset, + secret_store: StoreName::from(config.secret_store), + token_secret: config.access_token_secret, + uri, + backend_spec, + max_body_bytes: config.max_body_bytes, + } + } } impl FastlyTinybirdAuctionTelemetrySink { @@ -203,6 +232,149 @@ impl AuctionTelemetrySink for FastlyTinybirdAuctionTelemetrySink { } } +// --------------------------------------------------------------------------- +// Access telemetry: confirmed-delivery emitter +// --------------------------------------------------------------------------- + +/// Bucket count [`sampled_in`] maps `entropy` into. +/// +/// Large enough that `rate` values with several significant digits (e.g. +/// `0.015`) still land in a distinct bucket instead of rounding away, while +/// staying well inside `u64` range once multiplied by `rate`. +const ACCESS_SAMPLE_BUCKETS: u64 = 1_000_000; + +/// Decides whether one request's access-telemetry row should be emitted. +/// +/// `entropy` should vary from request to request — callers derive it from +/// the wall-clock event timestamp `XORed` with a cheap per-request value (see +/// the call site in `main.rs`). There is no `rand` crate dependency here: +/// the wasm32-wasip1 guest has no equivalent to `Math.random()`. Mapping +/// `entropy % ACCESS_SAMPLE_BUCKETS` into `[0, 1)` and comparing against +/// `rate` is not cryptographically uniform (the low bits of a timestamp are +/// not perfectly evenly distributed), but access-telemetry sampling only +/// needs an approximately even sample, not a provably unbiased one. +/// +/// `rate <= 0.0` always returns `false` and `rate >= 1.0` always returns +/// `true`, independent of `entropy`, so both boundary configurations behave +/// predictably. `0.0` cannot actually occur while `access_enabled` is `true` +/// (`Settings` validation requires `access_sample_rate > 0.0` in that case), +/// but this function stays total rather than leaning on that invariant. +#[must_use] +pub(crate) fn sampled_in(rate: f64, entropy: u64) -> bool { + if rate >= 1.0 { + return true; + } + if rate <= 0.0 { + return false; + } + let threshold = (rate * ACCESS_SAMPLE_BUCKETS as f64) as u64; + entropy % ACCESS_SAMPLE_BUCKETS < threshold +} + +/// Loads and validates the access-log APPEND token from the Fastly secret store. +/// +/// Constructs [`FastlyPlatformSecretStore`] directly instead of routing +/// through [`RuntimeServices`]: access-telemetry emission runs post-delivery +/// for every response class — including asset, admin, and error responses +/// that never build a route-scoped `RuntimeServices` — so the transport +/// context here must be adapter-owned and route-independent rather than +/// threaded from wherever the route happened to construct one. +fn load_access_token(target: &TinybirdEventsTarget) -> Result> { + let token = FastlyPlatformSecretStore + .get_string(&target.secret_store, &target.token_secret) + .change_context(TrustedServerError::Proxy { + message: "Tinybird access append token unavailable".to_owned(), + })?; + let token = token.trim().to_owned(); + if token.is_empty() { + return Err(Report::new(TrustedServerError::Proxy { + message: "Tinybird access append token is empty".to_owned(), + })); + } + Ok(token) +} + +/// Builds the Events API POST request for one access-log row. +fn build_access_events_request( + target: &TinybirdEventsTarget, + body: String, + auth_header: HeaderValue, +) -> Result> { + request_builder() + .method(Method::POST) + .uri(target.uri.as_str()) + .header(header::AUTHORIZATION, auth_header) + .header(header::CONTENT_TYPE, TINYBIRD_NDJSON_CONTENT_TYPE) + .body(Body::from(body)) + .change_context(TrustedServerError::Proxy { + message: "failed to build Tinybird Events API request".to_owned(), + }) +} + +/// Sends one confirmed access-log row to the Tinybird Events API and waits +/// for the response. +/// +/// Unlike [`FastlyTinybirdAuctionTelemetrySink::emit_auction_events`] (fire- +/// and-forget, dispatched mid-request so it never adds latency to the +/// response), this runs post-delivery: the response has already reached the +/// client, so there is no latency budget left to protect, and the send can +/// afford to wait for — and validate — the reply. `client` is the adapter's +/// stateless platform HTTP client in production +/// ([`crate::platform::FastlyPlatformHttpClient`]); accepting it as `&dyn +/// PlatformHttpClient` here (rather than that concrete type) is what lets +/// tests substitute a recording double instead of performing a real network +/// send, matching how [`RuntimeServices::http_client`] is consumed +/// elsewhere. `target` is derived from settings once at the post-send call +/// site rather than threaded through any per-route state. +/// +/// A non-2xx status is reported as `Err` naming the status; there is no +/// retry — the caller logs exactly one warning and moves on. +/// +/// # Errors +/// +/// Returns `Err` when the access-log APPEND token cannot be loaded, the +/// backend cannot be registered, the request cannot be built or sent, or the +/// Tinybird Events API responds with a non-2xx status. +pub(crate) async fn emit_access_event( + client: &dyn PlatformHttpClient, + target: &TinybirdEventsTarget, + row: String, +) -> Result<(), Report> { + let token = load_access_token(target)?; + let auth_header = FastlyTinybirdAuctionTelemetrySink::authorization_header(&token)?; + let backend_name = FastlyPlatformBackend + .ensure(&target.backend_spec) + .change_context(TrustedServerError::Proxy { + message: "Tinybird backend registration failed".to_owned(), + })?; + let request = build_access_events_request(target, row, auth_header)?; + + log::info!( + "sending access telemetry to Tinybird dataset={} host={} backend={}", + target.dataset, + target.api_host, + backend_name + ); + + let response = client + .send(PlatformHttpRequest::new(request, backend_name)) + .await + .change_context(TrustedServerError::Proxy { + message: "failed to send Tinybird access telemetry request".to_owned(), + })?; + + if response.response.status().is_success() { + Ok(()) + } else { + Err(Report::new(TrustedServerError::Proxy { + message: format!( + "Tinybird access telemetry request failed with status {}", + response.response.status() + ), + })) + } +} + fn tinybird_backend_spec(api_host: &str) -> PlatformBackendSpec { PlatformBackendSpec { scheme: "https".to_owned(), @@ -322,25 +494,28 @@ mod tests { body: Vec, } + /// Records outbound requests and, for [`PlatformHttpClient::send`] (the + /// blocking variant `emit_access_event` uses), returns a synthetic + /// response carrying `respond_status` instead of performing a real + /// network send. #[derive(Default)] struct RecordingHttpClient { requests: Mutex>, select_calls: Mutex, + respond_status: Mutex, } - #[async_trait::async_trait(?Send)] - impl PlatformHttpClient for RecordingHttpClient { - async fn send( - &self, - _request: PlatformHttpRequest, - ) -> Result> { - Err(Report::new(PlatformError::Unsupported)) + impl RecordingHttpClient { + /// Status [`PlatformHttpClient::send`] should reply with. Irrelevant + /// to auction-sink tests, which only exercise `send_async`. + fn respond_with(status: u16) -> Self { + Self { + respond_status: Mutex::new(status), + ..Self::default() + } } - async fn send_async( - &self, - request: PlatformHttpRequest, - ) -> Result> { + fn record(&self, request: PlatformHttpRequest) { let backend_name = request.backend_name; let (parts, body) = request.request.into_parts(); let headers = parts @@ -364,6 +539,35 @@ mod tests { .lock() .expect("should lock recorded requests") .push(recorded); + } + } + + #[async_trait::async_trait(?Send)] + impl PlatformHttpClient for RecordingHttpClient { + async fn send( + &self, + request: PlatformHttpRequest, + ) -> Result> { + self.record(request); + let status = *self + .respond_status + .lock() + .expect("should lock configured response status"); + let response = edgezero_core::http::response_builder() + .status( + edgezero_core::http::StatusCode::from_u16(status) + .expect("should build a valid test status code"), + ) + .body(edgezero_core::body::Body::empty()) + .expect("should build test response"); + Ok(PlatformResponse::new(response)) + } + + async fn send_async( + &self, + request: PlatformHttpRequest, + ) -> Result> { + self.record(request); Ok(PlatformPendingRequest::new(()).with_backend_name("tinybird-backend")) } @@ -443,6 +647,7 @@ mod tests { fn enabled_config() -> TinybirdSettings { TinybirdSettings { enabled: true, + auction_enabled: true, api_host: "api.us-east.aws.tinybird.co".to_owned(), secret_store: "ts_secrets".to_owned(), auction_dataset: "auction_events_raw".to_owned(), @@ -455,6 +660,39 @@ mod tests { } } + #[test] + fn sink_from_settings_disables_when_auction_enabled_is_false() { + let settings = Settings { + tinybird: TinybirdSettings { + auction_enabled: false, + ..enabled_config() + }, + ..Settings::default() + }; + + let sink = auction_sink_from_settings(&settings); + + assert!( + !sink.is_enabled(), + "auction telemetry should stay off when auction_enabled is false, even if tinybird.enabled is true" + ); + } + + #[test] + fn sink_from_settings_enables_when_both_toggles_are_true() { + let settings = Settings { + tinybird: enabled_config(), + ..Settings::default() + }; + + let sink = auction_sink_from_settings(&settings); + + assert!( + sink.is_enabled(), + "auction telemetry should be on when both tinybird.enabled and tinybird.auction_enabled are true" + ); + } + #[test] fn events_uri_targets_dataset_on_region_host() { assert_eq!( @@ -659,6 +897,89 @@ mod tests { ); } + #[test] + fn access_emitter_posts_ndjson_and_validates_2xx() { + // `ts_secrets`/`tinybird_access_append_token` is seeded in + // fastly.toml's `[local_server.secret_stores]` fixture (value + // "test-tinybird-access-append-token"), so `emit_access_event` can + // load a real token through Viceroy without a secret-store test + // double — the same fixture backs the auction-token secret used + // above. + let target = TinybirdEventsTarget::from_access_config(enabled_config()); + let http_client = RecordingHttpClient::respond_with(202); + let row = r#"{"status":200}"#.to_owned(); + + futures::executor::block_on(emit_access_event(&http_client, &target, row.clone())) + .expect("should accept a 202 response"); + + let requests = http_client + .requests + .lock() + .expect("should lock recorded requests"); + assert_eq!(requests.len(), 1, "should send exactly one request"); + assert_eq!( + requests[0].uri, + "https://api.us-east.aws.tinybird.co/v0/events?name=access_logs_raw" + ); + assert_eq!(requests[0].method, Method::POST.to_string()); + assert_eq!( + header_value(&requests[0].headers, header::AUTHORIZATION.as_str()), + Some("Bearer test-tinybird-access-append-token") + ); + assert_eq!( + std::str::from_utf8(&requests[0].body).expect("should record utf8 body"), + row, + "should send the row verbatim as the request body" + ); + } + + #[test] + fn access_emitter_warns_and_drops_on_non_2xx() { + let target = TinybirdEventsTarget::from_access_config(enabled_config()); + let http_client = RecordingHttpClient::respond_with(422); + + let result = futures::executor::block_on(emit_access_event( + &http_client, + &target, + r#"{"status":422}"#.to_owned(), + )); + + let error = result.expect_err("a 422 response should be reported as an error"); + assert!( + error.to_string().contains("422"), + "error should name the failing status: {error}" + ); + assert_eq!( + http_client + .requests + .lock() + .expect("should lock recorded requests") + .len(), + 1, + "should not retry after a non-2xx response" + ); + } + + #[test] + fn sampled_in_boundary_rates_are_unconditional() { + assert!( + sampled_in(1.0, 0), + "a 1.0 sample rate should always sample in" + ); + assert!( + sampled_in(1.0, u64::MAX), + "a 1.0 sample rate should always sample in regardless of entropy" + ); + assert!( + !sampled_in(0.0, 0), + "a 0.0 sample rate should never sample in" + ); + assert!( + !sampled_in(0.0, u64::MAX), + "a 0.0 sample rate should never sample in regardless of entropy" + ); + } + fn header_value<'a>(headers: &'a [(String, String)], name: &str) -> Option<&'a str> { headers .iter() diff --git a/crates/trusted-server-core/examples/local_dev_config.rs b/crates/trusted-server-core/examples/local_dev_config.rs new file mode 100644 index 000000000..acbb61b6c --- /dev/null +++ b/crates/trusted-server-core/examples/local_dev_config.rs @@ -0,0 +1,129 @@ +//! Generate a ready-to-use local dev config envelope for the Axum adapter. +//! +//! Reads `trusted-server.example.toml`, replaces the placeholder secrets with +//! random values, flips the flags a local smoke test needs, validates the +//! result through [`trusted_server_core::settings::Settings::from_toml`], and +//! prints the blob envelope JSON that the Axum adapter's +//! `TRUSTED_SERVER_CONFIG_{STORE}_{KEY}` environment variable expects. With +//! the default store and key both named `trusted_server_config`, the +//! concrete variable resolves (not a typo) to +//! `TRUSTED_SERVER_CONFIG_TRUSTED_SERVER_CONFIG_TRUSTED_SERVER_CONFIG`. +//! +//! The random values are time-and-pid seeded, not cryptographic. This tool +//! exists for throwaway local test instances only; never use its output for a +//! deployed service. +//! +//! Usage: +//! +//! ```text +//! cargo run -p trusted-server-core --example local_dev_config \ +//! --target -- [origin-url] [--realistic] +//! ``` +//! +//! `origin-url` defaults to `https://www.example.com`. By default every +//! response is forced `Cache-Control: private, no-store` so the Server-Timing +//! header is visible on all routes; pass `--realistic` to keep the origin's +//! own cache policy instead. + +use std::time::{SystemTime, UNIX_EPOCH}; + +/// Deliberately non-cryptographic generator for local placeholder secrets. +struct WeakRandom(u64); + +impl WeakRandom { + fn from_environment() -> Self { + let nanos = SystemTime::now() + .duration_since(UNIX_EPOCH) + .expect("should compute epoch time") + .subsec_nanos() as u64; + let secs = SystemTime::now() + .duration_since(UNIX_EPOCH) + .expect("should compute epoch time") + .as_secs(); + let pid = std::process::id() as u64; + Self(nanos ^ (secs << 20) ^ (pid << 40) ^ 0x9e37_79b9_7f4a_7c15) + } + + fn next(&mut self) -> u64 { + let mut x = self.0; + x ^= x << 13; + x ^= x >> 7; + x ^= x << 17; + self.0 = x; + x + } + + fn hex(&mut self, chars: usize) -> String { + let mut out = String::with_capacity(chars); + while out.len() < chars { + out.push_str(&format!("{:016x}", self.next())); + } + out.truncate(chars); + out + } +} + +#[allow(clippy::print_stdout, clippy::print_stderr)] +fn main() { + let args: Vec = std::env::args().skip(1).collect(); + let realistic = args.iter().any(|a| a == "--realistic"); + let origin = args + .iter() + .find(|a| !a.starts_with("--")) + .cloned() + .unwrap_or_else(|| "https://www.example.com".to_string()); + + let template = std::fs::read_to_string("trusted-server.example.toml") + .expect("should read trusted-server.example.toml from the repo root"); + + let mut random = WeakRandom::from_environment(); + let mut config = template + .replace( + "password = \"replace-with-admin-password-32-bytes\"", + &format!("password = \"{}\"", random.hex(48)), + ) + .replace( + "proxy_secret = \"change-me-proxy-secret\"", + &format!("proxy_secret = \"{}\"", random.hex(48)), + ) + .replace( + "passphrase = \"trusted-server-placeholder-secret\"", + &format!("passphrase = \"{}\"", random.hex(48)), + ) + .replace( + "server_timing_enabled = false", + "server_timing_enabled = true", + ); + + let origin_line = config + .lines() + .find(|line| line.starts_with("origin_url = ")) + .expect("should find the origin_url line in the template") + .to_string(); + config = config.replace(&origin_line, &format!("origin_url = \"{origin}\"")); + + if !realistic { + config = config.replace( + "# [response_headers]", + "[response_headers]\n\"Cache-Control\" = \"private, no-store\"", + ); + } + + let settings = trusted_server_core::settings::Settings::from_toml(&config) + .expect("should validate the generated local config"); + let data = serde_json::to_value(&settings).expect("should serialize settings"); + let generated_at = SystemTime::now() + .duration_since(UNIX_EPOCH) + .expect("should compute epoch time") + .as_secs() + .to_string(); + let envelope = edgezero_core::blob_envelope::BlobEnvelope::new(data, generated_at); + println!( + "{}", + serde_json::to_string(&envelope).expect("should serialize the envelope") + ); + eprintln!( + "local dev envelope generated: origin={origin} force_private={}", + !realistic + ); +} diff --git a/crates/trusted-server-core/src/access_telemetry.rs b/crates/trusted-server-core/src/access_telemetry.rs new file mode 100644 index 000000000..2aac6d7d3 --- /dev/null +++ b/crates/trusted-server-core/src/access_telemetry.rs @@ -0,0 +1,577 @@ +//! Access telemetry: route classification and the per-request access log row. +//! +//! Extends the reserved `access_logs_raw` Tinybird datasource with bounded, +//! content-free route identity (see [`RouteClass`] and +//! [`publisher_route_template`]) instead of the raw request path, which would +//! otherwise carry identifiers, search terms, and other user-generated +//! content into a 30-day dataset. See the design spec +//! `docs/superpowers/specs/2026-08-24-request-phase-timing-design.md` +//! section 9. + +use serde_json::json; + +use crate::request_timing::{AuctionWaitPlacement, TimingSnapshot}; + +/// Maximum length of a publisher path's first segment before +/// [`publisher_route_template`] rejects it to `/other/*`. Longer segments +/// are opaque-identifier or slug shaped (a UUID is 36 characters), and a +/// truncated prefix of either would still be identifying, so the segment +/// is rejected whole rather than truncated. +const MAX_SEGMENT_LEN: usize = 32; + +/// Maximum number of ASCII digits in a publisher path's first segment +/// before [`publisher_route_template`] rejects it to `/other/*`. Hex ids, +/// base36 ids, and reset tokens are digit-heavy; real section names carry +/// at most a year (`2026`) or a small version number, so a segment with +/// more digits than this is treated as an identifier, not a name. +const MAX_SEGMENT_DIGITS: usize = 7; + +/// Normalizes an HTTP method token into the bounded set of values stored in +/// the `method` `LowCardinality` column. +/// +/// HTTP permits arbitrary extension-method tokens (`PROPFIND`, `MKCOL`, or +/// any client-supplied garbage), and the token on an inbound request is +/// entirely client controlled. Capturing one verbatim into a 30-day +/// `LowCardinality(String)` column would let a single caller inflate that +/// column's cardinality without bound and would violate this dataset's +/// bounded-dimension privacy rule (see the module doc). Every standard +/// method maps to its uppercase form; anything else maps to `"other"`. Runs +/// inside [`access_event_row`] rather than at each capture site, so every +/// row-building path is covered regardless of how `method` was populated. +/// +/// # Examples +/// +/// ``` +/// use trusted_server_core::access_telemetry::normalize_method; +/// +/// assert_eq!(normalize_method("get"), "GET"); +/// assert_eq!(normalize_method("PROPFIND"), "other"); +/// assert_eq!(normalize_method(""), + "other", + "an unbounded client-controlled token must not reach the row verbatim" + ); + } + + #[test] + fn row_normalizes_method_even_when_snapshot_carries_a_raw_token() { + // The normalizer runs inside `access_event_row` so every row-building + // path is covered, regardless of what the snapshot's `method` field + // holds — a caller-controlled extension method must never leak into + // the row unnormalized. + let mut snapshot = unknown_snapshot(RouteClass::Other, "/other/*"); + snapshot.method = "PROPFIND".to_owned(); + let row = access_event_row(&snapshot, &TimingSnapshot::default(), 0); + let parsed: serde_json::Value = + serde_json::from_str(&row).expect("should serialize valid JSON"); + + assert_eq!(parsed["method"], "other"); + } +} diff --git a/crates/trusted-server-core/src/constants.rs b/crates/trusted-server-core/src/constants.rs index e1152b1e7..1f85facb8 100644 --- a/crates/trusted-server-core/src/constants.rs +++ b/crates/trusted-server-core/src/constants.rs @@ -34,6 +34,8 @@ pub const HEADER_X_TS_ENV: HeaderName = HeaderName::from_static("x-ts-env"); // Fastly environment variables pub const ENV_FASTLY_SERVICE_VERSION: &str = "FASTLY_SERVICE_VERSION"; pub const ENV_FASTLY_IS_STAGING: &str = "FASTLY_IS_STAGING"; +pub const ENV_FASTLY_SERVICE_ID: &str = "FASTLY_SERVICE_ID"; +pub const ENV_FASTLY_POP: &str = "FASTLY_POP"; // Common standard header names used across modules pub const HEADER_USER_AGENT: HeaderName = HeaderName::from_static("user-agent"); diff --git a/crates/trusted-server-core/src/ec/kv.rs b/crates/trusted-server-core/src/ec/kv.rs index 3572581ce..dc9885fde 100644 --- a/crates/trusted-server-core/src/ec/kv.rs +++ b/crates/trusted-server-core/src/ec/kv.rs @@ -810,6 +810,28 @@ mod tests { assert!(ts > 0, "should return a nonzero timestamp"); } + #[test] + fn kv_span_accumulates_across_graph_operations() { + let timings = crate::request_timing::RequestTimings::new(); + let graph = KvIdentityGraph::new(crate::platform::TimedKvStore::new( + crate::ec::kv_backend::test_support::InMemoryEcKv::new("test-store"), + timings.clone(), + )); + + graph + .create("ec-1", &live_entry()) + .expect("should create entry through the timed store"); + graph + .get("ec-1") + .expect("should read the entry back through the timed store"); + + timings.mark_headers_ready(); + assert!( + timings.snapshot().kv_ms.is_some(), + "should accumulate Phase::EcKv across both graph operations, not just the last write" + ); + } + #[test] fn serialize_entry_produces_valid_json() { let entry = KvEntry::tombstone(1000); diff --git a/crates/trusted-server-core/src/geo.rs b/crates/trusted-server-core/src/geo.rs index 63f7907f5..fe5785d26 100644 --- a/crates/trusted-server-core/src/geo.rs +++ b/crates/trusted-server-core/src/geo.rs @@ -48,6 +48,24 @@ impl GeoInfo { } } +/// Carries the outcome of a request-phase geo lookup across to +/// response-phase finalization, so a finalize consumer can reuse it instead +/// of performing a second lookup for the same request. +/// +/// Attached as a response extension on every exit path that attempted a +/// lookup, including the asset-route fallback (which does not carry an EC +/// finalize state). +#[derive(Debug, Clone)] +pub enum GeoLookupState { + /// No lookup has been attempted for this request. + NotAttempted, + /// A lookup ran and failed (or returned no result). This must not be + /// retried: finalize treats it the same as no geo info being available. + Attempted, + /// A lookup ran and resolved geo info. + Resolved(GeoInfo), +} + fn insert_geo_header(headers: &mut http::HeaderMap, name: http::header::HeaderName, value: &str) { match HeaderValue::from_str(value) { Ok(header_value) => { diff --git a/crates/trusted-server-core/src/integrations/registry.rs b/crates/trusted-server-core/src/integrations/registry.rs index 280eae847..376f5e492 100644 --- a/crates/trusted-server-core/src/integrations/registry.rs +++ b/crates/trusted-server-core/src/integrations/registry.rs @@ -893,6 +893,17 @@ impl IntegrationRegistry { self.find_route(method, path).is_some() } + /// Return true when at least one integration request filter is + /// registered. + /// + /// Adapters use this to decide whether to record a request-filter phase + /// timing span, so unconfigured deployments (no request filters) omit + /// that entry from observability output entirely. + #[must_use] + pub fn has_request_filters(&self) -> bool { + !self.inner.request_filters.is_empty() + } + /// Run pre-routing request filters. /// /// Request header mutations are applied immediately so later filters and diff --git a/crates/trusted-server-core/src/lib.rs b/crates/trusted-server-core/src/lib.rs index 48e92faed..de1bbad21 100644 --- a/crates/trusted-server-core/src/lib.rs +++ b/crates/trusted-server-core/src/lib.rs @@ -31,6 +31,7 @@ ) )] +pub mod access_telemetry; pub(crate) mod asset_image_optimizer; pub mod auction; pub mod auction_config_types; @@ -61,6 +62,7 @@ pub mod proxy; pub mod publisher; pub mod redacted; pub mod request_signing; +pub mod request_timing; pub mod response_privacy; pub mod rsc_flight; pub(crate) mod s3_sigv4; diff --git a/crates/trusted-server-core/src/platform/mod.rs b/crates/trusted-server-core/src/platform/mod.rs index 1c5bf4c2a..e6ed3ef90 100644 --- a/crates/trusted-server-core/src/platform/mod.rs +++ b/crates/trusted-server-core/src/platform/mod.rs @@ -42,6 +42,7 @@ mod template_assembly; mod template_cache; #[cfg(test)] pub(crate) mod test_support; +mod timed_kv; mod traits; mod types; @@ -67,6 +68,7 @@ pub use template_cache::{ TemplateEntry, TemplateMetadata, TemplateMetadataEncodeError, UnavailableTemplateCache, VaryHeaderValues, VarySpec, }; +pub use timed_kv::TimedKvStore; pub use traits::{PlatformBackend, PlatformConfigStore, PlatformGeo, PlatformSecretStore}; pub use types::{ ClientInfo, GeoInfo, PlatformBackendSpec, RuntimeServices, RuntimeServicesBuilder, StoreId, diff --git a/crates/trusted-server-core/src/platform/timed_kv.rs b/crates/trusted-server-core/src/platform/timed_kv.rs new file mode 100644 index 000000000..0594b7cef --- /dev/null +++ b/crates/trusted-server-core/src/platform/timed_kv.rs @@ -0,0 +1,180 @@ +//! Latency-only timing decorator for KV store handles. +//! +//! [`TimedKvStore`] wraps an inner store plus a [`RequestTimings`] handle and +//! records [`Phase::EcKv`] around every call. It implements both +//! [`PlatformKvStore`] (for consent-store access obtained through +//! [`RuntimeServices`](super::RuntimeServices)) and [`EcKvStore`] (for +//! [`KvIdentityGraph`](crate::ec::kv::KvIdentityGraph) construction sites), +//! because no single existing abstraction covers the whole `ts-kv` taxonomy: +//! EC graph operations go through [`EcKvStore`] while consent persistence +//! uses [`PlatformKvStore`] directly. +//! +//! The decorator measures store-call latency only: it never reads, parses, +//! or logs any value passing through it. + +use std::sync::Arc; +use std::time::Duration; + +use async_trait::async_trait; +use bytes::Bytes; +use edgezero_core::key_value_store::{KvError, KvPage, KvStore as PlatformKvStore}; +use error_stack::Report; + +use crate::ec::kv_backend::{EcKvLookup, EcKvStore, EcKvWrite, EcKvWriteOutcome}; +use crate::error::TrustedServerError; +use crate::request_timing::{Phase, RequestTimings}; + +/// Wraps `inner` plus a [`RequestTimings`] handle, recording [`Phase::EcKv`] +/// around every store call made through it. +pub struct TimedKvStore { + /// The wrapped store handle. + inner: S, + /// The request's phase-timing collector. + timings: RequestTimings, +} + +impl TimedKvStore { + /// Creates a decorator around `inner` that records into `timings`. + #[must_use] + pub fn new(inner: S, timings: RequestTimings) -> Self { + Self { inner, timings } + } +} + +#[async_trait(?Send)] +impl PlatformKvStore for TimedKvStore> { + async fn get_bytes(&self, key: &str) -> Result, KvError> { + let _span = self.timings.span(Phase::EcKv); + self.inner.get_bytes(key).await + } + + async fn put_bytes(&self, key: &str, value: Bytes) -> Result<(), KvError> { + let _span = self.timings.span(Phase::EcKv); + self.inner.put_bytes(key, value).await + } + + async fn put_bytes_with_ttl( + &self, + key: &str, + value: Bytes, + ttl: Duration, + ) -> Result<(), KvError> { + let _span = self.timings.span(Phase::EcKv); + self.inner.put_bytes_with_ttl(key, value, ttl).await + } + + async fn delete(&self, key: &str) -> Result<(), KvError> { + let _span = self.timings.span(Phase::EcKv); + self.inner.delete(key).await + } + + async fn list_keys_page( + &self, + prefix: &str, + cursor: Option<&str>, + limit: usize, + ) -> Result { + let _span = self.timings.span(Phase::EcKv); + self.inner.list_keys_page(prefix, cursor, limit).await + } +} + +impl EcKvStore for TimedKvStore { + fn store_name(&self) -> &str { + self.inner.store_name() + } + + fn lookup(&self, key: &str) -> Result, Report> { + let _span = self.timings.span(Phase::EcKv); + self.inner.lookup(key) + } + + fn insert( + &self, + key: &str, + write: EcKvWrite<'_>, + ) -> Result> { + let _span = self.timings.span(Phase::EcKv); + self.inner.insert(key, write) + } + + fn count_keys_with_prefix( + &self, + prefix: &str, + limit: u32, + ) -> Result> { + let _span = self.timings.span(Phase::EcKv); + self.inner.count_keys_with_prefix(prefix, limit) + } + + fn delete(&self, key: &str) -> Result<(), Report> { + let _span = self.timings.span(Phase::EcKv); + self.inner.delete(key) + } +} + +#[cfg(test)] +mod tests { + use std::time::Duration as StdDuration; + + use super::*; + use crate::ec::kv_backend::test_support::InMemoryEcKv; + + #[test] + fn ec_kv_store_operations_accumulate_into_ec_kv_phase() { + let timings = RequestTimings::new(); + let store = TimedKvStore::new(InMemoryEcKv::new("test-store"), timings.clone()); + + store + .insert( + "key-a", + EcKvWrite { + body: "{}", + metadata: "{}", + ttl: StdDuration::from_secs(60), + mode: crate::ec::kv_backend::EcKvWriteMode::Add, + }, + ) + .expect("should insert into the in-memory store"); + store.lookup("key-a").expect("should read back the entry"); + + timings.mark_headers_ready(); + assert!( + timings.snapshot().kv_ms.is_some(), + "should record Phase::EcKv across both store calls" + ); + } + + #[test] + fn store_name_is_not_timed() { + let timings = RequestTimings::new(); + let store = TimedKvStore::new(InMemoryEcKv::new("test-store"), timings.clone()); + + assert_eq!(store.store_name(), "test-store"); + timings.mark_headers_ready(); + assert!( + timings.snapshot().kv_ms.is_none(), + "store_name is a metadata accessor, not a store operation" + ); + } + + #[test] + fn platform_kv_store_operations_accumulate_into_ec_kv_phase() { + let timings = RequestTimings::new(); + let inner: Arc = Arc::new(crate::platform::UnavailableKvStore); + let store = TimedKvStore::new(inner, timings.clone()); + + // UnavailableKvStore errors on every call; the decorator still times + // the attempt regardless of outcome. + futures::executor::block_on(async { + let _ = store.get_bytes("key").await; + let _ = store.put_bytes("key", Bytes::from_static(b"value")).await; + }); + + timings.mark_headers_ready(); + assert!( + timings.snapshot().kv_ms.is_some(), + "should record Phase::EcKv even when the inner store errors" + ); + } +} diff --git a/crates/trusted-server-core/src/publisher.rs b/crates/trusted-server-core/src/publisher.rs index b0d63b82a..53d09bfc6 100644 --- a/crates/trusted-server-core/src/publisher.rs +++ b/crates/trusted-server-core/src/publisher.rs @@ -70,6 +70,7 @@ use crate::platform::{ contains_publisher_esi_directive, }; use crate::price_bucket::{PriceGranularity, price_bucket}; +use crate::request_timing::{AuctionWaitPlacement, Phase, RequestTimings}; use crate::response_privacy::{ apply_inactive_ad_stack_browser_cache_policy, cache_control_forbids_shared_storage, enforce_synthesized_html_cache_privacy, enforce_terminal_private_cache_privacy, @@ -90,21 +91,44 @@ const DEFAULT_PUBLISHER_FIRST_BYTE_TIMEOUT: Duration = Duration::from_secs(15); const HEADER_X_TS_TEMPLATE_CACHE: &str = "x-ts-template-cache"; const HEADER_X_TS_ASSEMBLY: &str = "x-ts-assembly"; -#[derive(Clone, Copy, PartialEq, Eq)] -enum TemplateCacheResponseState { +/// Outcome of a template-cache lookup/store attempt for one response. +/// +/// Set on every response that passes through the assembly pipeline via +/// [`set_template_cache_response_state`], which writes both the +/// `x-ts-template-cache` response header and this same value as a typed +/// response extension, so the two can never drift. Access telemetry reads +/// the extension rather than the header, since operator-configured response +/// headers can override a managed header but cannot touch extensions. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum TemplateCacheResponseState { + /// The cached template was found and reused. Hit, + /// No cached template existed; the cache store is reserved for this + /// content type. MissReserved, + /// No cached template existed; one was stored after assembly. MissStored, + /// No cached template existed; storing the freshly assembled template + /// failed. MissStoreError, + /// The request bypassed the cache lookup. BypassRequest, + /// The response bypassed the cache store. BypassResponse, + /// The response's content type is not supported by the template cache. Unsupported, + /// The cached template entry was invalid and could not be reused. Invalid, + /// A backend error prevented the cache lookup or store. BackendError, } impl TemplateCacheResponseState { - const fn as_str(self) -> &'static str { + /// Renders this variant as the string written to the + /// `x-ts-template-cache` header and the `template_cache_state` access + /// telemetry column. + #[must_use] + pub const fn as_str(self) -> &'static str { match self { Self::Hit => "hit", Self::MissReserved => "miss-reserved", @@ -127,6 +151,7 @@ fn set_template_cache_response_state( HEADER_X_TS_TEMPLATE_CACHE, HeaderValue::from_static(state.as_str()), ); + response.extensions_mut().insert(state); } #[derive(Clone, Copy, PartialEq, Eq)] @@ -1616,6 +1641,12 @@ pub struct OwnedProcessResponseParams { /// rescanned from the output, which cannot tell a `nonce` attribute from the same /// word inside a script. pub(crate) csp_nonce_observed: Option>, + /// Per-request phase-timing handle, carried into the streaming/buffered + /// finalizers so the `` seam wait can be recorded with the right + /// [`AuctionWaitPlacement`]. Cheap to clone (an `Arc` handle); a request that + /// never attached one to its extensions gets a fresh, unattached collector + /// that nothing ever renders. + pub(crate) timings: RequestTimings, } /// Response-authorized template cache insert inputs. The key is built before origin lookup; the @@ -1859,6 +1890,8 @@ pub async fn buffer_publisher_response_async( ¶ms.request_scheme, ¶ms.request_host, ), + timings: params.timings.clone(), + placement: AuctionWaitPlacement::PreHeader, }, ) .await; @@ -2018,6 +2051,7 @@ fn build_template_assembly_params( request_scheme: &str, price_granularity: PriceGranularity, ad_bids_state: AdBidsState, + timings: RequestTimings, ) -> OwnedProcessResponseParams { OwnedProcessResponseParams { csp_nonce_observed: None, @@ -2040,6 +2074,7 @@ fn build_template_assembly_params( price_granularity, gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings, } } @@ -2382,6 +2417,8 @@ pub async fn publisher_response_into_streaming_response( ¶ms.request_scheme, ¶ms.request_host, ), + timings: params.timings.clone(), + placement: AuctionWaitPlacement::InStream, }, ) .await; @@ -2500,6 +2537,7 @@ pub async fn publisher_response_into_streaming_response( &orchestrator, &services, &settings, + AuctionWaitPlacement::InStream, ) .await; // Collection reached a terminal result; disarm only now @@ -2521,6 +2559,8 @@ pub async fn publisher_response_into_streaming_response( ¶ms.request_scheme, ¶ms.request_host, ), + timings: params.timings.clone(), + placement: AuctionWaitPlacement::InStream, }; while let Some(step) = hold_step_next_chunk( @@ -2856,6 +2896,7 @@ pub async fn stream_publisher_body_async( orchestrator, services, settings, + AuctionWaitPlacement::PreHeader, ) .await; if body.is_stream() { @@ -2922,6 +2963,8 @@ pub async fn stream_publisher_body_async( services, settings, request_origin: request_origin(¶ms.request_scheme, ¶ms.request_host), + timings: params.timings.clone(), + placement: AuctionWaitPlacement::PreHeader, }, }, ) @@ -3489,6 +3532,12 @@ struct AuctionCollectDeps<'a> { settings: &'a Settings, /// Trusted request origin (`scheme://host`) for absolute inline creative URLs. request_origin: String, + /// Phase-timing handle the collect step records the auction wait into. + timings: RequestTimings, + /// Where this collect call sits relative to response headers: streaming + /// callers await inside the body already handed to the client, buffered + /// callers await before anything has been sent. + placement: AuctionWaitPlacement, } /// Run the close-body hold loop for HTML bodies, collecting the auction before @@ -3869,6 +3918,11 @@ async fn emit_abandoned_auction( /// Collect a dispatched auction before a non-HTML body streams: there is no /// `` to inject into, so bids are written to state up front and the /// auction telemetry completes immediately. +/// +/// `placement` records where this wait sits relative to response headers — the +/// caller decides, since this collector runs from both the buffered finalizer +/// (headers not yet committed) and the true streaming path (headers already +/// sent, this body only just started being polled). async fn collect_non_html_auction( dispatched: DispatchedAuction, telemetry: AuctionTelemetryCarry, @@ -3876,12 +3930,17 @@ async fn collect_non_html_auction( orchestrator: &AuctionOrchestrator, services: &RuntimeServices, settings: &Settings, + placement: AuctionWaitPlacement, ) { let auction_id = telemetry .auction_request .as_ref() .and_then(|_| diagnostics_auction_id(settings)); let placeholder = mediator_placeholder_request(); + // Qualified: `std::time::Instant::now()` panics on Cloudflare's + // `wasm32-unknown-unknown` target; this module's `Instant` import stays + // std for the pre-existing template-cache sites. + let wait_started = web_time::Instant::now(); let result = orchestrator .collect_dispatched_auction( dispatched, @@ -3889,6 +3948,9 @@ async fn collect_non_html_auction( &make_collect_context(settings, services, &placeholder), ) .await; + params + .timings + .record_auction_wait(placement, wait_started.elapsed()); let delivered_winner_slots = write_bids_to_state( &result.winning_bids, params.price_granularity, @@ -3930,6 +3992,8 @@ async fn collect_stream_auction( services, settings, request_origin, + timings, + placement, } = deps; let auction_id = telemetry .auction_request @@ -3938,9 +4002,14 @@ async fn collect_stream_auction( log::info!("body_close_hold_loop: collecting dispatched auction before held body tail"); let placeholder = mediator_placeholder_request(); let collect_ctx = make_collect_context(settings, services, &placeholder); + // Qualified: `std::time::Instant::now()` panics on Cloudflare's + // `wasm32-unknown-unknown` target; this module's `Instant` import stays + // std for the pre-existing template-cache sites. + let wait_started = web_time::Instant::now(); let result = orchestrator .collect_dispatched_auction(dispatched, services, &collect_ctx) .await; + timings.record_auction_wait(*placement, wait_started.elapsed()); log::info!( "body_close_hold_loop: collect complete - {} winning bid(s)", result.winning_bids.len() @@ -4044,6 +4113,14 @@ pub async fn handle_publisher_request( ) -> Result> { log::debug!("Proxying request to publisher_origin"); + // A defaulted handle records into nothing that ever renders, so tests + // that don't populate the request extension are unaffected. + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + // Adapter fallbacks prepare this before EC/cookie handling. Keep this // idempotent call as a direct-handler safety net and for focused tests. let gpt_diagnostics = @@ -4476,7 +4553,10 @@ pub async fn handle_publisher_request( // not be served a shared template even if that template is perfectly cacheable. let mut template_cache_reservation = None; if let Some(key) = template_cache_key.as_ref() { - match services.template_cache().lookup_or_reserve(key).await { + let template_cache_span = timings.span(Phase::TemplateCacheLookup); + let template_cache_lookup = services.template_cache().lookup_or_reserve(key).await; + drop(template_cache_span); + match template_cache_lookup { Ok(crate::platform::TemplateCacheLookup::Hit(entry)) => { log::debug!("template_cache hit: {} bytes", entry.body.len()); @@ -4526,6 +4606,7 @@ pub async fn handle_publisher_request( request_scheme, price_granularity, ad_bids_state.clone(), + timings.clone(), ); params.seam_ad_slots = seam_ad_slots.clone(); params.dispatched_auction = dispatched_auction.take(); @@ -4577,6 +4658,7 @@ pub async fn handle_publisher_request( platform_request = platform_request.with_cache_bypass(); } + let origin_span = timings.span(Phase::Origin); let mut response = match services.http_client().send(platform_request).await { Ok(platform_response) => platform_response.response, Err(err) => { @@ -4594,6 +4676,7 @@ pub async fn handle_publisher_request( })); } }; + drop(origin_span); log::debug!( "Publisher origin response received: status={}, header_count={}", @@ -4896,6 +4979,7 @@ pub async fn handle_publisher_request( dispatched_auction, price_granularity, gpt_diagnostics: Some(gpt_diagnostics), + timings: timings.clone(), }), }) } @@ -7532,6 +7616,7 @@ mod tests { price_granularity: Default::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), } } @@ -7737,6 +7822,35 @@ mod tests { .expect("should proxy publisher request") } + #[tokio::test] + async fn origin_span_covers_the_publisher_fetch() { + let settings = create_test_settings(); + let stub = Arc::new(StubHttpClient::new()); + stub.push_response_with_headers( + 200, + b"origin".to_vec(), + vec![(header::CONTENT_TYPE.as_str(), "text/html; charset=utf-8")], + ); + let services = + build_services_with_http_client(stub as Arc); + let mut request = HttpRequest::builder() + .method(Method::GET) + .uri("https://publisher.example/some-page") + .header(header::HOST, "publisher.example") + .body(EdgeBody::empty()) + .expect("should build request"); + let timings = RequestTimings::new(); + request.extensions_mut().insert(timings.clone()); + + let _response = run_publisher_proxy(&settings, &services, request).await; + + timings.mark_headers_ready(); + assert!( + timings.snapshot().origin_ms.is_some(), + "should record the Origin phase span around the publisher fetch" + ); + } + mod rendered_template_identity_tests { //! The gate the plan's Task 3 Step 2 actually asks for. //! @@ -8973,6 +9087,108 @@ mod tests { ); } + #[tokio::test] + async fn template_cache_response_extension_matches_the_header_on_every_transition() { + // The typed extension and the `x-ts-template-cache` header are written + // together by a single setter, so they must always agree — access + // telemetry reads the extension precisely because it cannot drift from + // what an operator-configured header override might otherwise show. + let stub = Arc::new(StubHttpClient::new()); + let cache = Arc::new(MemoryTemplateCache::default()); + let settings = Arc::new(settings_with_mode("esi")); + let services = services(Arc::clone(&stub), Arc::clone(&cache)); + + queue_shareable_html(&stub); + + let cold = run(&settings, &services, navigation_request()).await; + let cold_header = cold + .headers() + .get(HEADER_X_TS_TEMPLATE_CACHE) + .and_then(|value| value.to_str().ok()) + .map(str::to_owned); + let cold_extension = cold + .extensions() + .get::() + .map(|state| state.as_str()); + assert_eq!( + cold_extension, + cold_header.as_deref(), + "the cold-fill extension must match the header" + ); + assert_eq!(cold_extension, Some("miss-stored")); + + let warm = run(&settings, &services, navigation_request()).await; + let warm_header = warm + .headers() + .get(HEADER_X_TS_TEMPLATE_CACHE) + .and_then(|value| value.to_str().ok()) + .map(str::to_owned); + let warm_extension = warm + .extensions() + .get::() + .map(|state| state.as_str()); + assert_eq!( + warm_extension, + warm_header.as_deref(), + "the warm-hit extension must match the header" + ); + assert_eq!(warm_extension, Some("hit")); + } + + #[tokio::test] + async fn template_cache_span_recorded_only_when_lookup_runs() { + // Inline mode: no shared-cache key is ever computed, so the lookup + // never runs and the span is never recorded. + let inline_settings = create_test_settings(); + let inline_stub = Arc::new(StubHttpClient::new()); + inline_stub.push_response_with_headers( + 200, + b"origin".to_vec(), + vec![(header::CONTENT_TYPE.as_str(), "text/html; charset=utf-8")], + ); + let inline_services = build_services_with_http_client( + inline_stub as Arc, + ); + let mut inline_request = HttpRequest::builder() + .method(Method::GET) + .uri("https://publisher.example/some-page") + .header(header::HOST, "publisher.example") + .body(EdgeBody::empty()) + .expect("should build request"); + let inline_timings = RequestTimings::new(); + inline_request + .extensions_mut() + .insert(inline_timings.clone()); + + let _inline_response = + run_publisher_proxy(&inline_settings, &inline_services, inline_request).await; + + inline_timings.mark_headers_ready(); + assert!( + inline_timings.snapshot().template_cache_ms.is_none(), + "inline mode should never run the template-cache lookup" + ); + + // Shared-mode eligible: a matched slot plus a template-cache-eligible + // assembly mode compute a cache key, so the lookup runs and is timed. + let stub = Arc::new(StubHttpClient::new()); + let cache = Arc::new(MemoryTemplateCache::default()); + let settings = Arc::new(settings_with_mode("esi")); + let services = services(Arc::clone(&stub), Arc::clone(&cache)); + queue_shareable_html(&stub); + let mut request = navigation_request(); + let timings = RequestTimings::new(); + request.extensions_mut().insert(timings.clone()); + + let _response = run(&settings, &services, request).await; + + timings.mark_headers_ready(); + assert!( + timings.snapshot().template_cache_ms.is_some(), + "a shared-cache-eligible request should record the TemplateCacheLookup span" + ); + } + #[tokio::test] async fn only_the_cold_miss_uses_the_platform_assembler() { let stub = Arc::new(StubHttpClient::new()); @@ -14495,6 +14711,8 @@ mod tests { services: &services, settings: &settings, request_origin: String::new(), + timings: RequestTimings::new(), + placement: AuctionWaitPlacement::PreHeader, }, }; let mut output = Vec::new(); @@ -14544,6 +14762,8 @@ mod tests { services: &services, settings: &settings, request_origin: String::new(), + timings: RequestTimings::new(), + placement: AuctionWaitPlacement::PreHeader, }; // Passthrough processor: the ordering contract is about collection, not // HTML rewriting, so keep the emitted bytes verbatim. @@ -15420,6 +15640,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let mut output = Vec::new(); @@ -15473,6 +15694,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let mut output = Vec::new(); @@ -15515,6 +15737,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let body = EdgeBody::from_stream(futures::stream::iter(vec![Ok::<_, io::Error>( bytes::Bytes::from_static(b"live"), @@ -15635,6 +15858,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let body = EdgeBody::stream(futures::stream::iter(vec![ bytes::Bytes::from_static(b"body{background:url('https://origin.example.com/"), @@ -15693,6 +15917,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let compressed = gzip_encode(b"body{background:url('https://origin.example.com/asset.png')}"); @@ -15754,6 +15979,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let compressed = deflate_encode(b"body{background:url('https://origin.example.com/asset.png')}"); @@ -15815,6 +16041,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let compressed = brotli_encode(b"body{background:url('https://origin.example.com/asset.png')}"); @@ -15876,6 +16103,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let compressed = brotli_encode(b"body{background:url('https://origin.example.com/asset.png')}"); @@ -15925,6 +16153,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), } } @@ -16124,6 +16353,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let body = EdgeBody::stream(futures::stream::iter(vec![ bytes::Bytes::from_static(b"hello"), @@ -16193,6 +16423,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; // The `` that triggers bid injection lives in the SECOND gzip // member. `flate2::read::GzDecoder` decodes only the first member, so @@ -16261,6 +16492,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let body = EdgeBody::stream(futures::stream::iter(vec![bytes::Bytes::from_static( b"body{background:url('https://origin.example.com/asset.png')}", @@ -16322,6 +16554,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let publisher_response = PublisherResponse::Stream { response, @@ -16471,6 +16704,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), } } @@ -16861,6 +17095,7 @@ mod tests { price_granularity: PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), } }; let make_stream_response = || PublisherResponse::Stream { @@ -16923,6 +17158,149 @@ mod tests { assert_bodiless_abandoned(&buffered_sink); } + #[test] + fn streaming_seam_wait_records_in_stream_placement() { + // The true Fastly streaming path: `publisher_response_into_streaming_response` + // hands back a lazy body after headers have already been committed by + // `stream_to_client()`. The `` seam wait polled from inside that body + // must therefore be attributed `InStream`, never `PreHeader`. + let settings = Arc::new(create_test_settings()); + let registry = + IntegrationRegistry::new(&settings).expect("should create integration registry"); + let orchestrator = Arc::new(AuctionOrchestrator::new(settings.auction.clone())); + let timings = RequestTimings::new(); + + let mut params = make_stream_params(&settings, ""); + params.content_type = "text/html; charset=utf-8".to_string(); + params.dispatched_auction = Some(DispatchedAuction::empty_for_test( + test_auction_request(), + 500, + )); + params.auction_request = Some(test_auction_request()); + params.timings = timings.clone(); + + let response = Response::builder() + .status(StatusCode::OK) + .header(header::CONTENT_TYPE, "text/html; charset=utf-8") + .body(EdgeBody::empty()) + .expect("should build response"); + let body = EdgeBody::stream(futures::stream::iter(vec![ + bytes::Bytes::from_static(b"hello"), + bytes::Bytes::from_static(b""), + ])); + + let response = futures::executor::block_on(publisher_response_into_streaming_response( + PublisherResponse::Stream { + response, + body, + params: Box::new(params), + }, + &Method::GET, + Arc::clone(&settings), + ®istry, + Arc::clone(&orchestrator), + noop_services(), + )) + .expect("streaming finalize should succeed"); + + // The wait is only recorded once the lazy body is actually polled — the + // finalizer call above only constructs it. + let drained = futures::executor::block_on( + response + .into_body() + .into_bytes_bounded(settings.publisher.max_buffered_body_bytes), + ) + .expect("body should drain"); + assert!( + String::from_utf8_lossy(&drained).contains("hello"), + "should still stream the document" + ); + + let snapshot = timings.snapshot(); + assert_eq!( + snapshot.auction_wait_placement, + Some(AuctionWaitPlacement::InStream), + "the streaming seam wait must be attributed InStream" + ); + assert!( + snapshot.auction_wait_ms.is_some(), + "should record an auction wait duration" + ); + } + + #[test] + fn buffered_template_miss_records_pre_header_placement() { + // The buffered finalizer materializes the entire response — headers and + // body — before any of it reaches the client. Even though the wait runs + // through the same `` seam code path as the streaming finalizer + // above, headers have not committed here, so it must be attributed + // `PreHeader`. (This exercises the same collect step a shared-template + // authorized miss rides through: `template_cache_key`'s presence only + // changes what happens *after* collection — whether the transformed bytes + // are stored — not where the wait itself is measured.) + let settings = create_test_settings(); + let registry = + IntegrationRegistry::new(&settings).expect("should create integration registry"); + let orchestrator = AuctionOrchestrator::new(settings.auction.clone()); + let services = noop_services(); + let timings = RequestTimings::new(); + + let mut params = make_stream_params(&settings, ""); + params.content_type = "text/html; charset=utf-8".to_string(); + params.dispatched_auction = Some(DispatchedAuction::empty_for_test( + test_auction_request(), + 500, + )); + params.auction_request = Some(test_auction_request()); + params.timings = timings.clone(); + + let response = Response::builder() + .status(StatusCode::OK) + .header(header::CONTENT_TYPE, "text/html; charset=utf-8") + .body(EdgeBody::empty()) + .expect("should build response"); + let body = EdgeBody::stream(futures::stream::iter(vec![ + bytes::Bytes::from_static(b"hello"), + bytes::Bytes::from_static(b""), + ])); + + let response = futures::executor::block_on(buffer_publisher_response_async( + PublisherResponse::Stream { + response, + body, + params: Box::new(params), + }, + &Method::GET, + &settings, + ®istry, + &orchestrator, + &services, + )) + .expect("buffered finalize should succeed"); + + let html = String::from_utf8( + response + .into_body() + .into_bytes() + .unwrap_or_default() + .to_vec(), + ) + .expect("should be valid UTF-8"); + assert!(html.contains("hello"), "should still assemble the document"); + + let snapshot = timings.snapshot(); + assert_eq!( + snapshot.auction_wait_placement, + Some(AuctionWaitPlacement::PreHeader), + "the buffered finalizer's wait must be attributed PreHeader even though \ + it shares the seam code path with the streaming finalizer" + ); + assert!( + snapshot.auction_wait_ms.is_some(), + "should record an auction wait duration" + ); + } + #[test] fn publisher_response_streaming_finalize_processes_gzip_stream() { let compressed = @@ -17045,6 +17423,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let publisher_response = PublisherResponse::Stream { response, @@ -17117,6 +17496,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let mut output = Vec::new(); @@ -17172,6 +17552,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let bogus_body = EdgeBody::from(b"not gzip".to_vec()); @@ -17285,6 +17666,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let mut output = Vec::new(); stream_publisher_body(body, &mut output, ¶ms, &settings, ®istry) @@ -17347,6 +17729,7 @@ mod tests { price_granularity: crate::price_bucket::PriceGranularity::default(), gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings: RequestTimings::new(), }; let mut output = Vec::new(); diff --git a/crates/trusted-server-core/src/request_timing.rs b/crates/trusted-server-core/src/request_timing.rs new file mode 100644 index 000000000..8d1b92cc1 --- /dev/null +++ b/crates/trusted-server-core/src/request_timing.rs @@ -0,0 +1,566 @@ +//! 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; + +use http::{HeaderName, HeaderValue, Response}; +// `std::time::Instant::now()` panics on `wasm32-unknown-unknown` (the +// Cloudflare adapter's target); `web_time` re-exports std's `Instant` on +// every other target. +use web_time::Instant; + +use crate::cache_policy::cache_control_headers_are_private_or_no_store; + +/// `Server-Timing` header name. Not present in the `http` crate's `header` +/// module (unlike `CACHE_CONTROL` etc.), so declared locally following the +/// same `HeaderName::from_static` pattern used in +/// `trusted_server_core::constants`. +const HEADER_SERVER_TIMING: HeaderName = HeaderName::from_static("server-timing"); + +/// Number of [`Phase`] variants; sizes the fixed-slot duration array in +/// [`Inner`]. +const PHASE_COUNT: usize = 8; + +/// A distinct stage of request handling that duration can be attributed to. +/// +/// Variants map to fixed slots in [`RequestTimings`], in declaration order. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum Phase { + /// Time spent constructing the app/handler before request processing + /// begins. + AppBuild, + /// Time spent in request/response filtering (e.g. HTML rewriting). + Filter, + /// Time spent resolving geographic signals for the request. + Geo, + /// Time spent reading or writing the Edge Cookie key-value store. + EcKv, + /// Time spent waiting on the origin fetch. + Origin, + /// Time spent looking up a cached template. + TemplateCacheLookup, + /// Time spent waiting on the auction. Row-only: never rendered as a + /// `Server-Timing` header entry. + AuctionWait, + /// Time spent streaming the response body. Row-only: never rendered as + /// a `Server-Timing` header entry. + Stream, +} + +impl Phase { + /// Maps this variant to its fixed slot in the [`Inner::phases`] array. + fn index(self) -> usize { + match self { + Self::AppBuild => 0, + Self::Filter => 1, + Self::Geo => 2, + Self::EcKv => 3, + Self::Origin => 4, + Self::TemplateCacheLookup => 5, + Self::AuctionWait => 6, + Self::Stream => 7, + } + } + + /// `Server-Timing` 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, + } + } +} + +/// Where in the response the auction wait occurred. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum AuctionWaitPlacement { + /// The auction was awaited before response headers were sent. + PreHeader, + /// The auction was awaited while streaming the response body. + InStream, +} + +/// Mutable state behind [`RequestTimings`], guarded by a [`Mutex`]. +struct Inner { + /// Instant the request started; the reference point for elapsed marks. + t0: Instant, + /// Accumulated duration per [`Phase`], indexed by [`Phase::index`]. + phases: [Option; PHASE_COUNT], + /// Elapsed time at the first [`RequestTimings::mark_headers_ready`] call. + headers_ready_total: Option, + /// Elapsed time at the first [`RequestTimings::mark_request_elapsed`] + /// call. + request_elapsed: Option, + /// Placement recorded by the most recent + /// [`RequestTimings::record_auction_wait`] call. + auction_wait_placement: Option, + /// Response body size in bytes, set via + /// [`RequestTimings::set_resp_bytes`]. + resp_bytes: Option, +} + +/// Per-request phase timing collector. +/// +/// Cheap to clone (an [`Arc`] handle) and safe to share across threads and +/// async tasks handling the same request. Every method is infallible: lock +/// contention or poisoning silently drops the sample rather than blocking or +/// panicking. +#[derive(Clone)] +pub struct RequestTimings(Arc>); + +impl RequestTimings { + /// Starts a new collector with its clock reference (`t0`) set to now. + #[must_use] + pub fn new() -> Self { + Self(Arc::new(Mutex::new(Inner { + t0: Instant::now(), + phases: [None; PHASE_COUNT], + headers_ready_total: None, + request_elapsed: None, + auction_wait_placement: None, + resp_bytes: None, + }))) + } + + /// Accumulates `dur` into `phase`'s running total. + /// + /// Repeated calls for the same phase saturate-add rather than overwrite. + /// Drops the sample silently on lock contention or poisoning. + pub fn record(&self, phase: Phase, dur: Duration) { + let Ok(mut inner) = self.0.try_lock() else { + return; + }; + let index = phase.index(); + let accumulated = inner.phases[index] + .unwrap_or(Duration::ZERO) + .saturating_add(dur); + inner.phases[index] = Some(accumulated); + } + + /// Records an auction wait duration under [`Phase::AuctionWait`] and + /// stores its placement. + /// + /// Drops the sample silently on lock contention or poisoning. + pub fn record_auction_wait(&self, placement: AuctionWaitPlacement, dur: Duration) { + let Ok(mut inner) = self.0.try_lock() else { + return; + }; + let index = Phase::AuctionWait.index(); + let accumulated = inner.phases[index] + .unwrap_or(Duration::ZERO) + .saturating_add(dur); + inner.phases[index] = Some(accumulated); + inner.auction_wait_placement = Some(placement); + } + + /// Starts a guard that records elapsed time into `phase` when dropped. + #[must_use] + pub fn span(&self, phase: Phase) -> PhaseSpan { + PhaseSpan { + timings: self.clone(), + phase, + started: Instant::now(), + } + } + + /// Stamps the elapsed time since `t0` as `headers_ready_total`, the + /// first time this is called. + /// + /// Subsequent calls are no-ops (first call wins). Drops the sample + /// silently on lock contention or poisoning. + pub fn mark_headers_ready(&self) { + let Ok(mut inner) = self.0.try_lock() else { + return; + }; + if inner.headers_ready_total.is_none() { + inner.headers_ready_total = Some(inner.t0.elapsed()); + } + } + + /// Stamps the elapsed time since `t0` as `request_elapsed`, the first + /// time this is called. + /// + /// Subsequent calls are no-ops (first call wins). Drops the sample + /// silently on lock contention or poisoning. + pub fn mark_request_elapsed(&self) { + let Ok(mut inner) = self.0.try_lock() else { + return; + }; + if inner.request_elapsed.is_none() { + inner.request_elapsed = Some(inner.t0.elapsed()); + } + } + + /// Records the response body size in bytes. + /// + /// Drops the sample silently on lock contention or poisoning. + pub fn set_resp_bytes(&self, bytes: u64) { + let Ok(mut inner) = self.0.try_lock() else { + return; + }; + inner.resp_bytes = Some(bytes); + } + + /// Renders a `Server-Timing` header value, or `None` before + /// [`RequestTimings::mark_headers_ready`] has been called. + /// + /// `ts-total` is rendered first from `headers_ready_total`, followed by + /// the recorded header-bearing phases (`ts-appbuild`, `ts-filter`, + /// `ts-geo`, `ts-kv`, `ts-origin`, `ts-template-cache`) in enum + /// declaration order. Unrecorded phases are omitted. Durations are + /// rendered as milliseconds with one decimal place. Drops the sample + /// silently (returning `None`) on lock contention or poisoning. + #[must_use] + pub fn server_timing_value(&self) -> Option { + let inner = self.0.try_lock().ok()?; + let total = inner.headers_ready_total?; + let mut entries = vec![format_entry("ts-total", total)]; + for phase in HEADER_PHASES { + let Some(name) = phase.header_name() else { + continue; + }; + if let Some(dur) = inner.phases[phase.index()] { + entries.push(format_entry(name, dur)); + } + } + Some(entries.join(", ")) + } + + /// Captures the current state as a [`TimingSnapshot`]. + /// + /// Returns an all-`None` snapshot on lock contention or poisoning, + /// consistent with the infallibility of every other method. + #[must_use] + pub fn snapshot(&self) -> TimingSnapshot { + let Ok(inner) = self.0.try_lock() else { + return TimingSnapshot::default(); + }; + TimingSnapshot { + time_elapsed_ms: duration_ms(inner.headers_ready_total), + request_elapsed_ms: duration_ms(inner.request_elapsed), + appbuild_ms: duration_ms(inner.phases[Phase::AppBuild.index()]), + filter_ms: duration_ms(inner.phases[Phase::Filter.index()]), + geo_ms: duration_ms(inner.phases[Phase::Geo.index()]), + kv_ms: duration_ms(inner.phases[Phase::EcKv.index()]), + origin_ms: duration_ms(inner.phases[Phase::Origin.index()]), + template_cache_ms: duration_ms(inner.phases[Phase::TemplateCacheLookup.index()]), + auction_wait_ms: duration_ms(inner.phases[Phase::AuctionWait.index()]), + stream_ms: duration_ms(inner.phases[Phase::Stream.index()]), + auction_wait_placement: inner.auction_wait_placement, + resp_bytes: inner.resp_bytes, + } + } +} + +impl Default for RequestTimings { + fn default() -> Self { + Self::new() + } +} + +/// Stamps [`RequestTimings::mark_headers_ready`] and, when `enabled` and the +/// response is conclusively private, appends the rendered `Server-Timing` +/// header. +/// +/// Always stamps `mark_headers_ready` regardless of whether the header is +/// rendered, so the collector's `ts-total` reflects the moment headers +/// commit. Appends rather than overwrites so a pre-existing `Server-Timing` +/// value set upstream survives alongside the TS-owned set. A response is +/// never promoted to shared-cacheable just because the header would +/// otherwise be omitted: this only gates emission, it does not touch +/// `Cache-Control`. +/// +/// Generic over the response body type so every adapter's terminal layer can +/// call the same emission logic regardless of which body type its HTTP stack +/// uses. +pub fn append_server_timing_if_private( + response: &mut Response, + timings: &RequestTimings, + enabled: bool, +) { + timings.mark_headers_ready(); + + let conclusively_private = cache_control_headers_are_private_or_no_store(response.headers()); + if !enabled || !conclusively_private { + return; + } + + let Some(value) = timings.server_timing_value() else { + return; + }; + 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}"), + } +} + +/// The header-bearing phases (see [`Phase::header_name`]), in the enum +/// declaration order [`RequestTimings::server_timing_value`] renders them in. +const HEADER_PHASES: [Phase; 6] = [ + Phase::AppBuild, + Phase::Filter, + Phase::Geo, + Phase::EcKv, + Phase::Origin, + Phase::TemplateCacheLookup, +]; + +/// Formats one `Server-Timing` entry as `name;dur=`. +fn format_entry(name: &str, dur: Duration) -> String { + format!("{name};dur={:.1}", dur.as_secs_f64() * 1000.0) +} + +/// Converts a recorded [`Duration`] to whole milliseconds, saturating to +/// [`u32::MAX`] instead of overflowing. +fn duration_ms(dur: Option) -> Option { + dur.map(|dur| u32::try_from(dur.as_millis()).unwrap_or(u32::MAX)) +} + +/// RAII guard returned by [`RequestTimings::span`] that records its own +/// elapsed lifetime into the originating phase when dropped. +pub struct PhaseSpan { + /// The collector this span reports into on drop. + timings: RequestTimings, + /// The phase this span's elapsed time is recorded under. + phase: Phase, + /// The instant the span was created. + started: Instant, +} + +impl Drop for PhaseSpan { + fn drop(&mut self) { + self.timings.record(self.phase, self.started.elapsed()); + } +} + +/// A point-in-time, plain-data view of a [`RequestTimings`] collector. +/// +/// All durations are whole milliseconds; unrecorded phases are `None`. +#[derive(Debug, Clone, Default, PartialEq, Eq)] +pub struct TimingSnapshot { + /// Elapsed time from request start to + /// [`RequestTimings::mark_headers_ready`], in milliseconds. + pub time_elapsed_ms: Option, + /// Elapsed time from request start to + /// [`RequestTimings::mark_request_elapsed`], in milliseconds. + pub request_elapsed_ms: Option, + /// Accumulated [`Phase::AppBuild`] duration, in milliseconds. + pub appbuild_ms: Option, + /// Accumulated [`Phase::Filter`] duration, in milliseconds. + pub filter_ms: Option, + /// Accumulated [`Phase::Geo`] duration, in milliseconds. + pub geo_ms: Option, + /// Accumulated [`Phase::EcKv`] duration, in milliseconds. + pub kv_ms: Option, + /// Accumulated [`Phase::Origin`] duration, in milliseconds. + pub origin_ms: Option, + /// Accumulated [`Phase::TemplateCacheLookup`] duration, in milliseconds. + pub template_cache_ms: Option, + /// Accumulated [`Phase::AuctionWait`] duration, in milliseconds. + pub auction_wait_ms: Option, + /// Accumulated [`Phase::Stream`] duration, in milliseconds. + pub stream_ms: Option, + /// Placement recorded by the most recent + /// [`RequestTimings::record_auction_wait`] call. + pub auction_wait_placement: Option, + /// Response body size in bytes, set via + /// [`RequestTimings::set_resp_bytes`]. + pub resp_bytes: Option, +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn every_phase_index_is_unique_and_in_bounds() { + // `PHASE_COUNT` and `Phase::index()` are hand-synced; nothing at + // compile time ties them together. A new variant whose `index()` + // returns `PHASE_COUNT` would panic at runtime on first `record`, + // contradicting the module's no-panics claim, so this test fails + // first instead. (A variant missing from this list is a compile + // error via the exhaustive `match` in `index()` once added there.) + let phases = [ + Phase::AppBuild, + Phase::Filter, + Phase::Geo, + Phase::EcKv, + Phase::Origin, + Phase::TemplateCacheLookup, + Phase::AuctionWait, + Phase::Stream, + ]; + let mut seen = [false; PHASE_COUNT]; + for phase in phases { + let index = phase.index(); + assert!( + index < PHASE_COUNT, + "should be in bounds: {phase:?} -> {index}" + ); + assert!(!seen[index], "should be unique: {phase:?} -> {index}"); + seen[index] = true; + } + assert!( + seen.iter().all(|slot| *slot), + "should cover every phases-array slot" + ); + } + + #[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" + ); + } + + #[test] + fn append_server_timing_emits_on_private_response_when_enabled() { + let mut response = Response::builder() + .header("cache-control", "private, no-store") + .body(()) + .expect("should build a private response fixture"); + let timings = RequestTimings::new(); + + append_server_timing_if_private(&mut response, &timings, true); + + let header = response + .headers() + .get("server-timing") + .and_then(|value| value.to_str().ok()) + .expect("should emit a Server-Timing header"); + assert!( + header.starts_with("ts-total;dur="), + "should lead with the stored total: {header}" + ); + } + + #[test] + fn append_server_timing_marks_headers_ready_even_when_not_emitted() { + let mut response = Response::builder() + .header("cache-control", "max-age=60") + .body(()) + .expect("should build a shared-cacheable response fixture"); + let timings = RequestTimings::new(); + + append_server_timing_if_private(&mut response, &timings, true); + + assert!( + response.headers().get("server-timing").is_none(), + "should not emit on a shared-cacheable response" + ); + assert!( + timings.server_timing_value().is_some(), + "should still stamp mark_headers_ready so ts-total reflects the freeze point" + ); + } +} diff --git a/crates/trusted-server-core/src/settings.rs b/crates/trusted-server-core/src/settings.rs index ddc8ac612..1aecf80a9 100644 --- a/crates/trusted-server-core/src/settings.rs +++ b/crates/trusted-server-core/src/settings.rs @@ -1704,9 +1704,16 @@ impl Proxy { /// Direct Tinybird Events API telemetry configuration. #[derive(Debug, Clone, Deserialize, Serialize)] pub struct TinybirdSettings { - /// Master enablement for auction telemetry ingestion. + /// Master enablement for Tinybird telemetry. Required by both auction and + /// access-log emission; each is independently toggled below. #[serde(default)] pub enabled: bool, + /// Emit auction telemetry when `enabled`. Defaults to `true` so existing + /// configs preserve their current auction-emission behavior after + /// upgrading; set `false` to silence auction events while keeping + /// `enabled` on for other Tinybird telemetry (e.g. `access_enabled`). + #[serde(default = "default_true")] + pub auction_enabled: bool, /// Regional Tinybird API host, without scheme or path. #[serde(default)] pub api_host: String, @@ -1719,19 +1726,26 @@ pub struct TinybirdSettings { /// Secret key containing the auction datasource APPEND token. #[serde(default = "default_tinybird_auction_token_secret")] pub auction_token_secret: String, - /// Reserved for future access-log telemetry. + /// Emit access-log telemetry when `enabled`, independent of + /// `auction_enabled`. /// - /// `true` is rejected until an access-log emitter is wired, so operators - /// cannot enable a setting that silently emits nothing. + /// `true` requires `enabled`, non-empty `api_host`/`secret_store`/ + /// `access_dataset`/`access_token_secret`, `max_body_bytes > 0`, and + /// `access_sample_rate > 0.0`. This prevents an armed-but-silent sampler + /// that enables the flag but emits nothing. #[serde(default)] pub access_enabled: bool, - /// Future access-log Events API datasource name. + /// Access-log Events API datasource name. Required non-empty when + /// `access_enabled`. #[serde(default = "default_tinybird_access_dataset")] pub access_dataset: String, - /// Future Secret Store key containing the access-log datasource APPEND token. + /// Secret Store key containing the access-log datasource APPEND token. + /// Required non-empty when `access_enabled`. #[serde(default = "default_tinybird_access_token_secret")] pub access_token_secret: String, - /// Future fraction of requests to emit for optional access telemetry. + /// Fraction of requests to emit for access telemetry. Must be greater + /// than `0.0` when `access_enabled`, so an operator cannot enable access + /// telemetry while sampling it away entirely. #[serde(default)] pub access_sample_rate: f64, /// Defensive maximum NDJSON body size for one Events API request. @@ -1767,6 +1781,7 @@ impl Default for TinybirdSettings { fn default() -> Self { Self { enabled: false, + auction_enabled: default_true(), api_host: String::new(), secret_store: default_tinybird_secret_store(), auction_dataset: default_tinybird_auction_dataset(), @@ -1790,6 +1805,12 @@ impl TinybirdSettings { self.access_token_secret = self.access_token_secret.trim().to_owned(); } + /// Validate this settings block, including the access-telemetry matrix: + /// `access_enabled` requires `enabled`, a non-empty `api_host`, + /// `secret_store`, `access_dataset`, and `access_token_secret`, a + /// `max_body_bytes` above the defensive floor enforced below, and an + /// `access_sample_rate` greater than `0.0`. Auction emission is + /// independently gated by `auction_enabled` and validated the same way. fn prepare_runtime(&mut self) -> Result<(), Report> { self.normalize(); if !(0.0..=1.0).contains(&self.access_sample_rate) { @@ -1802,9 +1823,9 @@ impl TinybirdSettings { message: "tinybird.max_body_bytes must be at least 1024".to_owned(), })); } - if self.access_enabled { + if self.access_enabled && !self.enabled { return Err(Report::new(TrustedServerError::Configuration { - message: "tinybird.access_enabled is reserved for future access-log telemetry; no emitter is currently wired".to_owned(), + message: "tinybird.access_enabled requires tinybird.enabled".to_owned(), })); } if !self.enabled { @@ -1818,10 +1839,19 @@ impl TinybirdSettings { .to_owned(), })); } - if self.enabled { + if self.auction_enabled { validate_tinybird_dataset(&self.auction_dataset, "tinybird.auction_dataset")?; validate_tinybird_secret(&self.auction_token_secret, "tinybird.auction_token_secret")?; } + if self.access_enabled { + validate_tinybird_dataset(&self.access_dataset, "tinybird.access_dataset")?; + validate_tinybird_secret(&self.access_token_secret, "tinybird.access_token_secret")?; + if self.access_sample_rate <= 0.0 { + return Err(Report::new(TrustedServerError::Configuration { + message: "tinybird.access_sample_rate must be > 0 when tinybird.access_enabled is true".to_owned(), + })); + } + } Ok(()) } } @@ -2588,6 +2618,29 @@ pub enum AuctionDebugCommentFormat { Pretty, } +/// Request-observability toggles exposed to operators. +/// +/// The default table must stay omitted from serialized config blobs: this +/// struct denies unknown fields, so an older binary loading a config blob +/// carrying an `[observability]` table it does not know would reject it, +/// breaking rollback. See [`Settings::observability`]. +#[derive(Debug, Clone, Default, PartialEq, Deserialize, Serialize)] +#[serde(deny_unknown_fields)] +pub struct ObservabilitySettings { + /// Emit the `Server-Timing` response header with per-phase request + /// timing. Defaults to `false` (off). + #[serde(default)] + pub server_timing_enabled: bool, +} + +impl ObservabilitySettings { + /// True when every field is at its default, i.e. observability is fully + /// disabled and the table can be omitted from serialized output. + fn is_default(&self) -> bool { + *self == Self::default() + } +} + /// Tester-cookie endpoint configuration. #[derive(Debug, Default, Clone, Deserialize, Serialize)] pub struct TesterCookieConfig { @@ -2633,6 +2686,12 @@ pub struct Settings { pub tinybird: TinybirdSettings, #[serde(default)] pub debug: DebugConfig, + /// Request-observability toggles. The default table is omitted from + /// serialized config blobs so a config round-tripped without change + /// still parses under a prior binary's schema; see + /// [`ObservabilitySettings`]. + #[serde(default, skip_serializing_if = "ObservabilitySettings::is_default")] + pub observability: ObservabilitySettings, } impl Settings { @@ -3354,6 +3413,14 @@ mod tests { use crate::redacted::Redacted; use crate::test_support::tests::{crate_test_settings_str, create_test_settings}; + /// Parses `extra` appended to the shared test fixture TOML, mirroring the + /// `format!("{}\n...", crate_test_settings_str())` pattern used throughout + /// this module's other tests. + fn settings_from_toml_with(extra: &str) -> Result> { + let toml = format!("{}\n{extra}", crate_test_settings_str()); + Settings::from_toml(&toml) + } + #[test] fn auction_debug_comment_options_default_matches_serde_defaults() { let opts = AuctionDebugCommentOptions::default(); @@ -3565,17 +3632,83 @@ mod tests { } #[test] - fn tinybird_access_enabled_is_rejected_until_emitter_is_wired() { - let toml = format!( - "{}\n[tinybird]\naccess_enabled = true\n", - crate_test_settings_str() + fn tinybird_access_enabled_with_full_config_is_accepted() { + let settings = settings_from_toml_with( + "[tinybird]\nenabled = true\napi_host = \"api.example.com\"\naccess_enabled = true\naccess_sample_rate = 1.0\n", + ) + .expect("should accept a fully-specified access telemetry config"); + assert!( + settings.tinybird.access_enabled, + "should enable access emission" ); + } - let err = Settings::from_toml(&toml) - .expect_err("should reject access telemetry before emitter exists"); + #[test] + fn access_enabled_requires_tinybird_enabled() { + // access_enabled = true with tinybird.enabled omitted (defaults + // false) must be rejected: access telemetry cannot run without the + // master toggle on. + let err = settings_from_toml_with( + "[tinybird]\napi_host = \"api.example.com\"\naccess_enabled = true\naccess_sample_rate = 1.0\n", + ) + .expect_err("should reject access telemetry without tinybird.enabled"); assert!( format!("{err:?}").contains("tinybird.access_enabled"), - "should report unsupported tinybird.access_enabled setting: {err:?}" + "should name the field: {err:?}" + ); + } + + #[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" + ); + } + + #[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" ); } diff --git a/docs/guide/configuration.md b/docs/guide/configuration.md index a1f172429..675aaf40a 100644 --- a/docs/guide/configuration.md +++ b/docs/guide/configuration.md @@ -77,6 +77,8 @@ fail and the service will return its startup-error response. | `[request_signing]` | Ed25519 request signing | | `[auction]` | Auction orchestration | | `[integrations.*]` | Partner integrations (Prebid, Next.js, etc.) | +| `[observability]` | Server-Timing header emission | +| `[tinybird]` | Auction and access telemetry transport | ## Example: Production Setup @@ -1805,6 +1807,130 @@ Rollback to the legacy entry point is no longer controlled by runtime config keys. Use the normal deployment rollback path to restore a pre-cleanup service version if that is required. +## Observability and Access Telemetry Configuration + +Settings for the `Server-Timing` response header and the sampled +access-telemetry sink. Both are off by default and are independent switches: +enabling one does not enable the other. + +### `[observability]` + +| Field | Type | Required | Default | Description | +| ----------------------- | ------- | -------- | ------- | ------------------------------------------------------------------- | +| `server_timing_enabled` | Boolean | No | `false` | Append request-phase timings to the `Server-Timing` response header | + +**Purpose**: Surfaces per-phase request timing (`ts-total` plus recorded +phases such as `ts-appbuild`, `ts-filter`, `ts-geo`, `ts-kv`, `ts-origin`, and +`ts-template-cache`) as a standard `Server-Timing` header, in milliseconds +with one decimal place. An unrecorded phase is omitted from the header +rather than rendered as zero. + +**Emission is conservative**: the header is appended only on responses that +are conclusively private, meaning `Cache-Control` contains `private` or +`no-store`. A response that is heuristically cacheable, carries a bare +`max-age`, or has no cache header at all never receives the header, because a +shared-cache object would otherwise replay one request's timings for its +entire stored lifetime. The long-lived, shared-cacheable `tsjs` asset route is +the concrete case this excludes. The header is appended, never inserted, so +an origin-supplied `Server-Timing` value and any entries the fronting +delivery layer adds are preserved alongside the TS entries. + +The Axum adapter applies the same private-response rule at its own terminal +point before serializing the response, and emits the header only; it does not +send access-telemetry rows. + +**Example**: + +```toml +[observability] +server_timing_enabled = true +``` + +**Environment Override**: + +```bash +TRUSTED_SERVER__OBSERVABILITY__SERVER_TIMING_ENABLED=true +``` + +::: tip Present-but-false by default +`server_timing_enabled` ships as `false` in the base operator config rather +than being left out, even though `false` is also its default. The +environment-variable overlay can only override a leaf that already exists in +the parsed TOML; it cannot create a missing one. Keeping the leaf present lets +`TRUSTED_SERVER__OBSERVABILITY__SERVER_TIMING_ENABLED` take effect without an +extra edit to add the table first. +::: + +### `[tinybird]` access telemetry keys + +`[tinybird]` configures a shared Events API transport (`enabled`, `api_host`, +`secret_store`, and per-sink dataset and token fields) used by two +independent emitters: auction telemetry (`auction_dataset`, +`auction_token_secret`) and access telemetry. The keys below cover the +access-telemetry sink and the shared enable flags. + +| Field | Type | Required | Default | Description | +| -------------------- | ------- | ------------------------------------ | ------- | ------------------------------------------------------------------------------- | +| `enabled` | Boolean | Yes, when `access_enabled` | `false` | Master switch for the shared Tinybird transport (host, store, credentials) | +| `auction_enabled` | Boolean | No | `true` | Independently gates auction telemetry emission, decoupled from access telemetry | +| `access_enabled` | Boolean | No | `false` | Enables the sampled access-telemetry row sent after each response is delivered | +| `access_sample_rate` | Float | Yes (`> 0.0`), when `access_enabled` | `0.0` | Fraction (`0.0`-`1.0`) of requests to emit an access-telemetry row for | + +**Purpose**: `access_enabled` and `auction_enabled` gate the two Tinybird +sinks separately so that turning on one does not silently turn on (or leave +off) the other; a settings test locks this decoupling in both directions. +Setting `access_enabled = true` with `access_sample_rate = 0.0` is rejected at +config load as an armed-but-silent configuration; use `access_enabled` itself +to turn the sink off, not the sample rate. Enabling `access_enabled` also +requires the shared transport fields (`enabled`, non-empty `api_host`, +`secret_store`, `access_dataset`, `access_token_secret`, and a positive +`max_body_bytes`) to already be set. + +**Example**: + +```toml +[tinybird] +enabled = true +api_host = "api.tinybird.example.com" +secret_store = "ts_secrets" +auction_enabled = true + +# Access-log telemetry, decoupled from auction emission. +access_enabled = true +access_dataset = "access_logs_raw" +access_token_secret = "tinybird_access_append_token" +access_sample_rate = 0.05 +max_body_bytes = 1048576 +``` + +**Environment Override**: + +```bash +TRUSTED_SERVER__TINYBIRD__ACCESS_ENABLED=true +TRUSTED_SERVER__TINYBIRD__ACCESS_SAMPLE_RATE=0.05 +TRUSTED_SERVER__TINYBIRD__AUCTION_ENABLED=true +``` + +A sampled request emits one access-telemetry row to `access_dataset` after +the response has already been delivered to the client, so ingest never delays +the response the reader sees. + +### Deploy and rollback ordering + +::: warning `Settings` rejects unknown fields; order matters +Both `[observability].server_timing_enabled` and the new `[tinybird]` access +keys are new fields on a config schema that uses `deny_unknown_fields`, so an +older binary fails to load a config that carries them. + +**Deploying**: upgrade the binary first, then push a config containing the +new fields second. Never push a config with these fields while a +pre-observability binary can still receive it. + +**Rolling back**: reverse the order. Remove the `[observability]` table and +any new `[tinybird]` access keys from the config and push that first, then +roll back the binary second. +::: + ## Validation ### Automatic Validation 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..9ff3905f4 --- /dev/null +++ b/docs/superpowers/plans/2026-08-24-request-phase-timing.md @@ -0,0 +1,1038 @@ +# 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.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 + 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 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** + +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 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] +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: 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** + +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 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. Buffered responses keep the Task 3 complete-on-return + semantics; `body_mode` distinguishes the regimes in the row. + +- [ ] **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` (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:** + +- 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`). `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** + +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(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** + +```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** 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** + +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. 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..214d146a1 --- /dev/null +++ b/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md @@ -0,0 +1,564 @@ +# Request phase timing: Server-Timing subtimings and access telemetry + +**Date:** 2026-08-24 +**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). + +--- + +## 1. Problem + +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 +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 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 + +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. 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. Requests served entirely by the +fronting cache never reach the guest and produce neither header entries nor rows. + +## 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 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. +- 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 + +``` +adapter entry (T0) + | 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 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) +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) + 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; 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 +``` + +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`, + `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`, + `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 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 + 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 + 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 + `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` | 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`) 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 | + +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 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 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: + +| 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 + +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), 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 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 emission rule at its terminal point before response +serialization, with adapter-specific phase semantics (section 8a). + +## 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`). + +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 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 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). + +## 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; nullable because a contended lock drop can lose the +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 +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. +- Rejection is whole-segment, never truncation: a segment is dropped to `/other/*` + when it fails the charset allowlist, exceeds 32 characters, or carries more than 7 + ASCII digits. The character allowlist alone does not bound identity (`[a-z0-9_-]` + is exactly the alphabet of UUIDs, hex ids, and reset tokens), and a truncated + prefix of any of those is still identifying, so the length and digit bounds reject + the segment outright. +- 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, overlong + segments, UUIDs, hex ids, reset tokens, and full article slugs 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): + +``` +`service_id` LowCardinality(String), -- FASTLY_SERVICE_ID; immutable deployment identity +`publisher_domain` LowCardinality(String), -- matches auction schema +`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 +`auction_wait_placement` LowCardinality(String), -- pre_header | in_stream | none +`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(String), -- from the typed response extension, not the public header +`country` LowCardinality(String), +`ts_version` LowCardinality(String), +`pop` LowCardinality(String) -- FASTLY_POP, 'unknown' when absent +``` + +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 +invisible by construction and the dashboard documentation says so. + +Sorting key: `(toDate(event_ts), service_id, publisher_domain, env, route_class, +pop, status)`. Every column carries a `json:$.` path (the Events API rejects +NDJSON into a datasource without JSONPaths, discovered live); `event_date` was +dropped in favor of the sorting-key expression because a DEFAULT column cannot +carry a JSONPath the producer never sends. Grafana time filtering uses `$__timeFilter(event_ts)` and every panel query +also carries an `event_date` predicate so the primary index prunes; rollout validates +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 + +- `AccessTelemetrySnapshot`: built unconditionally at the freeze point, before + `into_parts()` consumes the response. It captures method, status, route metadata + (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 + `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. +- 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. +- Budget: at `access_sample_rate = 1.0` this adds one backend request per request to + 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)` 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 +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`, 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 + 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. + +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. 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 + +```toml +[observability] +# Append TS phase timings to the Server-Timing response header. +server_timing_enabled = false # example default +``` + +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. + +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 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 + 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. + +## 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 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, auction-wait placement recording. +- Adapter tests (Fastly via Viceroy, Axum native): header present and well-formed on a + 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`; 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, 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. 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 + `performance.getEntriesByType('navigation')[0].serverTiming` shows `ts-*` entries + 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. + 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, 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, 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; 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 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. diff --git a/tinybird/datasources/access_logs_raw.datasource b/tinybird/datasources/access_logs_raw.datasource index 42f214e07..062b884ba 100644 --- a/tinybird/datasources/access_logs_raw.datasource +++ b/tinybird/datasources/access_logs_raw.datasource @@ -1,19 +1,39 @@ DESCRIPTION > - Optional sampled Trusted Server access telemetry rows. Disabled by default in Fastly config. + Per-request phase-timing telemetry rows, sampled and emitted post-send by the edge service. SCHEMA > - `event_ts` DateTime64(3), - `method` LowCardinality(String), - `path` String, - `status` UInt16, - `time_elapsed_ms` UInt32, - `cache_state` LowCardinality(Nullable(String)), - `country` LowCardinality(String), - `sample_rate` Float64, - `event_date` Date DEFAULT toDate(event_ts) + `event_ts` DateTime64(3) `json:$.event_ts`, + `method` LowCardinality(String) `json:$.method`, + `status` UInt16 `json:$.status`, + `time_elapsed_ms` Nullable(UInt32) `json:$.time_elapsed_ms`, + `sample_rate` Float64 `json:$.sample_rate`, + `service_id` LowCardinality(String) `json:$.service_id`, + `publisher_domain` LowCardinality(String) `json:$.publisher_domain`, + `env` LowCardinality(String) `json:$.env`, + `route_class` LowCardinality(String) `json:$.route_class`, + `route_template` String `json:$.route_template`, + `body_mode` LowCardinality(String) `json:$.body_mode`, + `auction_wait_placement` LowCardinality(String) `json:$.auction_wait_placement`, + `appbuild_ms` Nullable(UInt32) `json:$.appbuild_ms`, + `filter_ms` Nullable(UInt32) `json:$.filter_ms`, + `geo_ms` Nullable(UInt32) `json:$.geo_ms`, + `kv_ms` Nullable(UInt32) `json:$.kv_ms`, + `origin_ms` Nullable(UInt32) `json:$.origin_ms`, + `template_cache_ms` Nullable(UInt32) `json:$.template_cache_ms`, + `auction_wait_ms` Nullable(UInt32) `json:$.auction_wait_ms`, + `stream_ms` Nullable(UInt32) `json:$.stream_ms`, + `request_elapsed_ms` Nullable(UInt32) `json:$.request_elapsed_ms`, + `resp_bytes` Nullable(UInt64) `json:$.resp_bytes`, + `template_cache_state` LowCardinality(String) `json:$.template_cache_state`, + `country` LowCardinality(String) `json:$.country`, + `ts_version` LowCardinality(String) `json:$.ts_version`, + `pop` LowCardinality(String) `json:$.pop` ENGINE "MergeTree" -ENGINE_SORTING_KEY "event_date, path, status, method" -TTL "event_date + INTERVAL 30 DAY" +ENGINE_SORTING_KEY "toDate(event_ts), service_id, publisher_domain, env, route_class, pop, status" +TTL "toDate(event_ts) + INTERVAL 30 DAY" + +FORWARD_QUERY > + SELECT event_ts, method, status, time_elapsed_ms, sample_rate, service_id, publisher_domain, env, route_class, route_template, body_mode, auction_wait_placement, appbuild_ms, filter_ms, geo_ms, kv_ms, origin_ms, template_cache_ms, auction_wait_ms, stream_ms, request_elapsed_ms, resp_bytes, template_cache_state, country, ts_version, pop TOKEN ts_access_ingest APPEND diff --git a/tinybird/fixtures/access_logs_raw.ndjson b/tinybird/fixtures/access_logs_raw.ndjson new file mode 100644 index 000000000..3c82c5ca6 --- /dev/null +++ b/tinybird/fixtures/access_logs_raw.ndjson @@ -0,0 +1 @@ +{"event_ts":"2026-06-23 12:00:00.000","method":"GET","status":200,"time_elapsed_ms":145,"sample_rate":0.1,"service_id":"abc123","publisher_domain":"test-publisher.com","env":"production","route_class":"publisher_html","route_template":"/news/*","body_mode":"streamed","auction_wait_placement":"in_stream","appbuild_ms":12,"filter_ms":5,"geo_ms":3,"kv_ms":8,"origin_ms":25,"template_cache_ms":10,"auction_wait_ms":45,"stream_ms":18,"request_elapsed_ms":145,"resp_bytes":8192,"template_cache_state":"hit","country":"US","ts_version":"v1.2.3","pop":"SFO"} diff --git a/trusted-server.example.toml b/trusted-server.example.toml index 71f0f8f78..c52a299b3 100644 --- a/trusted-server.example.toml +++ b/trusted-server.example.toml @@ -222,6 +222,35 @@ verbosity = "redacted" # JSON request/response bodies remain strings exactly as captured. format = "compact" +[tinybird] +enabled = false +# Regional Tinybird API host, no scheme/port/path, e.g. "api.us-east.aws.tinybird.co". +api_host = "" +secret_store = "ts_secrets" +auction_dataset = "auction_events_raw" +auction_token_secret = "tinybird_auction_append_token" +# Defaults to true: existing configs keep emitting auction telemetry once +# `enabled` is turned on. Set false to silence auction events while keeping +# `enabled` on for other Tinybird telemetry (e.g. `access_enabled`). +auction_enabled = true +# Access-log telemetry, decoupled from auction emission. `true` requires +# `enabled`, non-empty api_host/secret_store/access_dataset/access_token_secret, +# max_body_bytes > 0, and access_sample_rate > 0.0; an armed-but-silent sampler +# (access_enabled = true with access_sample_rate = 0) fails config load. +access_enabled = false +access_dataset = "access_logs_raw" +access_token_secret = "tinybird_access_append_token" +# Fraction (0.0-1.0) of requests to emit for access telemetry when access_enabled. +access_sample_rate = 0.0 +# Defensive maximum NDJSON body size, in bytes, for one Events API request. +max_body_bytes = 1048576 + +[observability] +# Keep this leaf present so the environment override can apply; the overlay +# cannot create a missing configuration leaf. The Server-Timing header stays +# off until enabled. +server_timing_enabled = false + [creative_opportunities] # Set to false to disable server-side ad templates while retaining slot definitions # and direct POST /auction callers. Structurally inactive templates use the