diff --git a/.gitignore b/.gitignore index 24b9e06aa..238e6b133 100644 --- a/.gitignore +++ b/.gitignore @@ -63,3 +63,7 @@ src/*.html # leftover local build artifacts (node_modules, target, dist) that remain on disk. /crates/js/ /crates/integration-tests/ + +# Wrangler config generated by the Cloudflare integration-test harness from +# wrangler.toml at run time; regenerated on every run. +wrangler.integration.generated.toml diff --git a/Cargo.lock b/Cargo.lock index e915a0ea8..a60f1d4ec 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -832,7 +832,7 @@ version = "3.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "faf9468729b8cbcea668e36183cb69d317348c2e08e994829fb56ebfdfbaac34" dependencies = [ - "windows-sys 0.61.2", + "windows-sys 0.48.0", ] [[package]] @@ -1498,7 +1498,7 @@ dependencies = [ [[package]] name = "edgezero-adapter" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?rev=683202c66948146ec360f490126f1d60f920288b#683202c66948146ec360f490126f1d60f920288b" +source = "git+https://github.com/stackpop/edgezero?rev=ab444946fcacb1d44c020c6079abb6ba29231402#ab444946fcacb1d44c020c6079abb6ba29231402" dependencies = [ "toml", ] @@ -1506,7 +1506,7 @@ dependencies = [ [[package]] name = "edgezero-adapter-axum" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?rev=683202c66948146ec360f490126f1d60f920288b#683202c66948146ec360f490126f1d60f920288b" +source = "git+https://github.com/stackpop/edgezero?rev=ab444946fcacb1d44c020c6079abb6ba29231402#ab444946fcacb1d44c020c6079abb6ba29231402" dependencies = [ "anyhow", "async-trait", @@ -1534,7 +1534,7 @@ dependencies = [ [[package]] name = "edgezero-adapter-cloudflare" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?rev=683202c66948146ec360f490126f1d60f920288b#683202c66948146ec360f490126f1d60f920288b" +source = "git+https://github.com/stackpop/edgezero?rev=ab444946fcacb1d44c020c6079abb6ba29231402#ab444946fcacb1d44c020c6079abb6ba29231402" dependencies = [ "anyhow", "async-trait", @@ -1557,7 +1557,7 @@ dependencies = [ [[package]] name = "edgezero-adapter-fastly" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?rev=683202c66948146ec360f490126f1d60f920288b#683202c66948146ec360f490126f1d60f920288b" +source = "git+https://github.com/stackpop/edgezero?rev=ab444946fcacb1d44c020c6079abb6ba29231402#ab444946fcacb1d44c020c6079abb6ba29231402" dependencies = [ "anyhow", "async-stream", @@ -1586,7 +1586,7 @@ dependencies = [ [[package]] name = "edgezero-adapter-spin" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?rev=683202c66948146ec360f490126f1d60f920288b#683202c66948146ec360f490126f1d60f920288b" +source = "git+https://github.com/stackpop/edgezero?rev=ab444946fcacb1d44c020c6079abb6ba29231402#ab444946fcacb1d44c020c6079abb6ba29231402" dependencies = [ "anyhow", "async-trait", @@ -1613,7 +1613,7 @@ dependencies = [ [[package]] name = "edgezero-cli" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?rev=683202c66948146ec360f490126f1d60f920288b#683202c66948146ec360f490126f1d60f920288b" +source = "git+https://github.com/stackpop/edgezero?rev=ab444946fcacb1d44c020c6079abb6ba29231402#ab444946fcacb1d44c020c6079abb6ba29231402" dependencies = [ "chrono", "clap", @@ -1638,7 +1638,7 @@ dependencies = [ [[package]] name = "edgezero-core" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?rev=683202c66948146ec360f490126f1d60f920288b#683202c66948146ec360f490126f1d60f920288b" +source = "git+https://github.com/stackpop/edgezero?rev=ab444946fcacb1d44c020c6079abb6ba29231402#ab444946fcacb1d44c020c6079abb6ba29231402" dependencies = [ "anyhow", "async-compression", @@ -1669,7 +1669,7 @@ dependencies = [ [[package]] name = "edgezero-macros" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?rev=683202c66948146ec360f490126f1d60f920288b#683202c66948146ec360f490126f1d60f920288b" +source = "git+https://github.com/stackpop/edgezero?rev=ab444946fcacb1d44c020c6079abb6ba29231402#ab444946fcacb1d44c020c6079abb6ba29231402" dependencies = [ "log", "proc-macro2", @@ -2557,7 +2557,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1c91d8cffac8849493a82233811bd02b2b183b8cf39bf704de0fa0841b737595" dependencies = [ "bstr", - "hashbrown 0.17.1", + "hashbrown 0.16.1", ] [[package]] @@ -6546,6 +6546,7 @@ dependencies = [ "futures", "log", "log-fastly", + "rand 0.8.6", "serde", "serde_json", "toml", @@ -7210,7 +7211,7 @@ version = "0.1.11" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c2a7b1c03c876122aa43f3020e6c3c3ee5c05081c9a00739faf7503aeba10d22" dependencies = [ - "windows-sys 0.61.2", + "windows-sys 0.48.0", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index f5c81ecf4..c00b3a265 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -56,12 +56,14 @@ cssparser = "0.36" derive_more = { version = "2.0", features = ["display", "error"] } directories = "5" ed25519-dalek = { version = "2.2", features = ["rand_core"] } -edgezero-adapter-axum = { git = "https://github.com/stackpop/edgezero", rev = "683202c66948146ec360f490126f1d60f920288b", default-features = false } -edgezero-adapter-cloudflare = { git = "https://github.com/stackpop/edgezero", rev = "683202c66948146ec360f490126f1d60f920288b", default-features = false } -edgezero-adapter-fastly = { git = "https://github.com/stackpop/edgezero", rev = "683202c66948146ec360f490126f1d60f920288b", default-features = false } -edgezero-adapter-spin = { git = "https://github.com/stackpop/edgezero", rev = "683202c66948146ec360f490126f1d60f920288b", default-features = false } -edgezero-cli = { git = "https://github.com/stackpop/edgezero", rev = "683202c66948146ec360f490126f1d60f920288b" } -edgezero-core = { git = "https://github.com/stackpop/edgezero", rev = "683202c66948146ec360f490126f1d60f920288b", default-features = false } +# Temporary integration pin for EdgeZero PR #389. Before merging TS into main, +# replace all six pins with the approved EdgeZero release tag and revalidate. +edgezero-adapter-axum = { git = "https://github.com/stackpop/edgezero", rev = "ab444946fcacb1d44c020c6079abb6ba29231402", default-features = false } +edgezero-adapter-cloudflare = { git = "https://github.com/stackpop/edgezero", rev = "ab444946fcacb1d44c020c6079abb6ba29231402", default-features = false } +edgezero-adapter-fastly = { git = "https://github.com/stackpop/edgezero", rev = "ab444946fcacb1d44c020c6079abb6ba29231402", default-features = false } +edgezero-adapter-spin = { git = "https://github.com/stackpop/edgezero", rev = "ab444946fcacb1d44c020c6079abb6ba29231402", default-features = false } +edgezero-cli = { git = "https://github.com/stackpop/edgezero", rev = "ab444946fcacb1d44c020c6079abb6ba29231402" } +edgezero-core = { git = "https://github.com/stackpop/edgezero", rev = "ab444946fcacb1d44c020c6079abb6ba29231402", default-features = false } env_logger = "0.11" error-stack = "0.6" esi = "0.7.2" diff --git a/crates/trusted-server-adapter-axum/Cargo.toml b/crates/trusted-server-adapter-axum/Cargo.toml index 94ad02170..1c0158e6f 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,7 +28,8 @@ 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] @@ -36,4 +38,3 @@ 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 caba714d6..7bd46b12e 100644 --- a/crates/trusted-server-adapter-axum/src/app.rs +++ b/crates/trusted-server-adapter-axum/src/app.rs @@ -1,6 +1,7 @@ use core::future::Future; use std::sync::Arc; +use edgezero_adapter_axum::service::EdgeZeroAxumService; use edgezero_core::app::Hooks; use edgezero_core::context::RequestContext; use edgezero_core::error::EdgeError; @@ -615,16 +616,10 @@ impl Hooks for TrustedServerApp { "TrustedServer" } + /// Returns the bare router without terminal timing; serve with + /// [`Self::dev_server_service`] to preserve `Server-Timing` emission. 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 } } @@ -646,6 +641,43 @@ impl TrustedServerApp { Ok(build_router(&state)) } + /// The dev server's fully configured tower service: the application + /// router wrapped in the terminal timing layer + /// ([`crate::timing::TimingService`]), with `server_timing_enabled` + /// read from the same settings snapshot that built the router. + /// + /// This is the standard construction path for serving this adapter. + /// [`Hooks::routes`] satisfies the `Hooks` trait contract and returns + /// the bare router without the timing layer; callers who serve traffic + /// should use this instead so `server_timing_enabled` is never + /// silently discarded. + #[must_use] + pub fn dev_server_service() -> crate::timing::TimingService { + let (router, server_timing_enabled) = Self::routes_with_server_timing_flag(); + crate::timing::TimingService::new(EdgeZeroAxumService::new(router), server_timing_enabled) + } + + /// 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. The Axum dev server builds its application + /// state once and reuses the same [`RouterService`] for every request. + #[must_use] + 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) + } + /// Build the full router with explicit settings and runtime services. /// /// Each request receives a clone of the supplied services, allowing callers 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..4cf781dc8 100644 --- a/crates/trusted-server-adapter-axum/src/main.rs +++ b/crates/trusted-server-adapter-axum/src/main.rs @@ -1,6 +1,15 @@ -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 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 +29,68 @@ fn main() { }; log::info!("Listening on http://{}", config.addr); - let router = TrustedServerApp::routes(); - if let Err(err) = AxumDevServer::with_config(router, config).run() { + let service = TrustedServerApp::dev_server_service(); + if let Err(err) = run(service, 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( + service: TimingService, + config: AxumDevServerConfig, +) -> std::io::Result<()> { + let runtime = RuntimeBuilder::new_multi_thread().enable_all().build()?; + runtime.block_on(serve(service, config)) +} + +async fn serve( + service: TimingService, + config: AxumDevServerConfig, +) -> std::io::Result<()> { + let listener = TcpListener::bind(config.addr).await.map_err(|error| { + std::io::Error::new( + error.kind(), + format!("failed to bind dev server to {}: {error}", config.addr), + ) + })?; + + 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..4b223f53d --- /dev/null +++ b/crates/trusted-server-adapter-axum/src/timing.rs @@ -0,0 +1,435 @@ +//! 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 reuses the generic +//! handle in request extensions or creates one, exposing it through the +//! [`RequestTimings`](trusted_server_core::request_timing::RequestTimings) +//! facade. Downstream core handlers can record into it. The wrapper stamps +//! `mark_headers_ready` on the way back 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` because the tower boundary is the terminal +//! freeze point: by the time a response reaches this layer -- after +//! `RouterService::oneshot` inside `EdgeZeroAxumService::call` has +//! converted any dispatch error into a plain response -- every response is +//! covered uniformly regardless of how routing produced it, and the +//! position survives future routing changes. (In this application's router +//! a catch-all fallback spans every path and publisher method, so +//! router-generated 404/405s that bypass middleware are close to +//! unreachable today; the outer position does not depend on them.) +//! +//! `/health` is excluded by path match before a +//! [`RequestTimings`](trusted_server_core::request_timing::RequestTimings) +//! collector is even created: this wrapper bypasses timing for every method +//! on that path, leaving any preinstalled handle unchanged. +//! +//! 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 bypass this wrapper for every method. +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(); + + // Bypass installation and finalization for `/health`, regardless of method. + // A preinstalled collector remains available to the inner service. + 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::from_extensions(req.extensions()).unwrap_or_else(|| { + let timings = RequestTimings::new(); + req.extensions_mut().insert(timings.handle().clone()); + timings + }); + + 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_preserves_preinstalled_collector_and_origin() { + let timings = RequestTimings::new(); + timings.record( + trusted_server_core::request_timing::Phase::Filter, + std::time::Duration::from_millis(7), + ); + tokio::time::sleep(std::time::Duration::from_millis(20)).await; + let router = RouterService::builder() + .get("/private", |ctx: RequestContext| async move { + let timings = RequestTimings::from_extensions(ctx.request().extensions()) + .expect("should receive preinstalled collector"); + assert_eq!( + timings.snapshot().filter_ms, + Some(7), + "should preserve upstream phase" + ); + timings.mark_auction_dispatched(); + assert!( + timings + .snapshot() + .auction_dispatched_ms + .expect("should mark dispatch") + >= 20, + "should preserve the pre-aged origin" + ); + private_ok_response() + }) + .build(); + let terminal = TimingService::new(EdgeZeroAxumService::new(router), true); + let upstream_timings = timings.clone(); + let mut upstream = service_fn(move |mut req: Request| { + req.extensions_mut() + .insert(upstream_timings.handle().clone()); + let mut service = terminal.clone(); + async move { service.call(req).await } + }); + let request = Request::builder() + .uri("/private") + .body(AxumBody::empty()) + .expect("should build request"); + let response = upstream + .ready() + .await + .expect("should be ready") + .call(request) + .await + .expect("should handle request"); + let value = header(&response, "server-timing").expect("should render private timing"); + assert!( + value.contains("ts-filter;dur=7.0"), + "should render upstream phase: {value}" + ); + assert!( + timings + .snapshot() + .time_elapsed_ms + .expect("should stamp original handle") + >= 20, + "terminal rendering should use the original clock" + ); + } + + #[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_suppresses_timing_when_edge_cache_header_collides_with_private_cache_control() { + let router = RouterService::builder() + .get("/collision", |_ctx: RequestContext| async { + Ok(response_builder() + .status(StatusCode::OK) + .header("cache-control", "private, no-store") + .header("cdn-cache-control", "max-age=60") + .body(EdgeBody::from("ok")) + .expect("should build a response with conflicting cache directives")) + }) + .build(); + let mut service = TimingService::new(EdgeZeroAxumService::new(router), true); + + let request = Request::builder() + .uri("/collision") + .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::OK); + assert_eq!( + header(&response, "cdn-cache-control").as_deref(), + Some("max-age=60") + ); + assert!( + header(&response, "server-timing").is_none(), + "must not expose timing when a CDN header can make the private response cacheable" + ); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn axum_suppresses_header_when_flag_is_off() { + let router = RouterService::builder() + .get("/private", |_ctx: RequestContext| async { + private_ok_response() + }) + .build(); + let mut service = TimingService::new(EdgeZeroAxumService::new(router), false); + + 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"); + + assert!( + header(&response, "server-timing").is_none(), + "should not emit server-timing when server_timing_enabled is false" + ); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn axum_round_trips_phase_timings_recorded_in_the_handler() { + // The collector crosses the adapter boundary as a request extension; + // this pins the round trip end to end: a phase recorded inside a + // core-style handler must come back out in the rendered header, so + // a future adapter conversion that drops request extensions fails + // here instead of silently losing every phase. + let router = RouterService::builder() + .get("/private", |ctx: RequestContext| async move { + if let Some(timings) = RequestTimings::from_extensions(ctx.request().extensions()) { + timings.record( + trusted_server_core::request_timing::Phase::Filter, + std::time::Duration::from_millis(7), + ); + } + 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-filter;dur=7.0"), + "a phase recorded in the handler should survive the adapter round trip: {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() { + for method in [axum::http::Method::GET, axum::http::Method::POST] { + for path in ["/health", "/health?probe=1"] { + for preinstalled in [false, true] { + let timings = RequestTimings::new(); + let inner = service_fn(move |req: Request| async move { + assert_eq!( + RequestTimings::from_extensions(req.extensions()).is_some(), + preinstalled, + "health bypass should not install or remove a handle" + ); + Ok::<_, Infallible>( + Response::builder() + .header("cache-control", "private") + .body(AxumBody::empty()) + .expect("should build private response"), + ) + }); + let mut service = TimingService::new(inner, true); + let mut request = Request::builder() + .method(method.clone()) + .uri(path) + .body(AxumBody::empty()) + .expect("should build request"); + if preinstalled { + request.extensions_mut().insert(timings.handle().clone()); + } + let response = service + .ready() + .await + .expect("should be ready") + .call(request) + .await + .expect("should not fail"); + assert!( + header(&response, "server-timing").is_none(), + "health should not emit timing" + ); + assert_eq!( + timings.snapshot().time_elapsed_ms, + None, + "health bypass should not finalize timing" + ); + } + } + } + } +} diff --git a/crates/trusted-server-adapter-cloudflare/src/app.rs b/crates/trusted-server-adapter-cloudflare/src/app.rs index 87b9567e7..3a7445e05 100644 --- a/crates/trusted-server-adapter-cloudflare/src/app.rs +++ b/crates/trusted-server-adapter-cloudflare/src/app.rs @@ -40,6 +40,7 @@ use trusted_server_core::publisher::{ use trusted_server_core::request_signing::{ handle_trusted_server_discovery, handle_verify_signature, }; +use trusted_server_core::request_timing::RequestTimingMiddleware; use trusted_server_core::settings::Settings; use crate::middleware::{AuthMiddleware, FinalizeResponseMiddleware, SanitizeRequestMiddleware}; @@ -602,6 +603,7 @@ fn build_router(state: &Arc) -> RouterService { // any middleware registered ahead of it would observe the // shared-secret authentication header. .middleware(SanitizeRequestMiddleware::new(Arc::clone(&state.settings))) + .middleware(RequestTimingMiddleware::default().with_excluded_paths(&["/health"])) .middleware(FinalizeResponseMiddleware::new(Arc::clone(&state.settings))) .middleware(AuthMiddleware::new(Arc::clone(&state.settings))) .get( diff --git a/crates/trusted-server-adapter-cloudflare/src/middleware.rs b/crates/trusted-server-adapter-cloudflare/src/middleware.rs index 14efed56a..51a5956d1 100644 --- a/crates/trusted-server-adapter-cloudflare/src/middleware.rs +++ b/crates/trusted-server-adapter-cloudflare/src/middleware.rs @@ -56,9 +56,9 @@ impl Middleware for SanitizeRequestMiddleware { /// (injected by the Cloudflare Workers runtime). On the native host target the /// header is absent, so `X-Geo-Info-Available: false` is emitted. /// -/// Registered directly inside [`SanitizeRequestMiddleware`] and ahead of -/// [`AuthMiddleware`] so that every outgoing response — including auth-rejected -/// ones — carries a consistent set of headers. +/// Registered inside [`RequestTimingMiddleware`](trusted_server_core::request_timing::RequestTimingMiddleware) and ahead of [`AuthMiddleware`] +/// so that every outgoing response — including auth-rejected ones — carries a +/// consistent set of headers. pub struct FinalizeResponseMiddleware { settings: Arc, } @@ -161,6 +161,8 @@ pub(crate) fn apply_finalize_headers( #[cfg(test)] mod tests { use super::*; + use edgezero_core::router::RouterService; + use trusted_server_core::request_timing::{RequestTimingMiddleware, RequestTimings}; use std::collections::HashMap; use std::sync::Mutex; @@ -180,10 +182,10 @@ mod tests { .expect("should build empty test response") } - fn empty_ctx() -> RequestContext { + fn ctx_for_path(path: &str) -> RequestContext { let req = request_builder() .method(Method::GET) - .uri("/test") + .uri(path) .header("x-reader-ip", "198.51.100.7") .header("x-reader-ip-auth", "fictional-shared-secret-0123456789") .body(Body::empty()) @@ -191,6 +193,10 @@ mod tests { RequestContext::new(req, PathParams::new(HashMap::new())) } + fn empty_ctx() -> RequestContext { + ctx_for_path("/test") + } + fn settings_with_response_headers(headers: Vec<(&str, &str)>) -> Settings { // Build from explicit test settings: the settings baked into the // binary contain placeholder secrets that `get_settings()` rejects @@ -289,6 +295,77 @@ mod tests { ); } + #[test] + fn request_timing_middleware_preserves_shared_handle_and_health_policy() { + for method in [Method::GET, Method::POST] { + for path in ["/test", "/health", "/health?probe=1", "/health/child"] { + for preinstalled in [false, true] { + let route_path = path.split('?').next().expect("should have path"); + let expected = preinstalled || route_path != "/health"; + let timings = RequestTimings::new(); + timings.record( + trusted_server_core::request_timing::Phase::Filter, + std::time::Duration::from_millis(7), + ); + std::thread::sleep(std::time::Duration::from_millis(2)); + let router = RouterService::builder() + .middleware( + RequestTimingMiddleware::default().with_excluded_paths(&["/health"]), + ) + .middleware( + RequestTimingMiddleware::default().with_excluded_paths(&["/health"]), + ) + .route(route_path, method.clone(), move |ctx: RequestContext| async move { + let installed = RequestTimings::from_extensions(ctx.request().extensions()); + assert_eq!(installed.is_some(), expected, "should preserve exact health policy"); + if let Some(installed) = installed { + if preinstalled { + assert_eq!(installed.snapshot().filter_ms, Some(7), "should retain upstream facts"); + installed.mark_auction_dispatched(); + assert!(installed.snapshot().auction_dispatched_ms.expect("should mark dispatch") >= 2, + "should retain upstream origin"); + } else { + assert_eq!(installed.snapshot(), trusted_server_core::request_timing::TimingSnapshot::default(), + "should install independent empty facts"); + } + installed.record_auction_wait( + trusted_server_core::request_timing::AuctionWaitPlacement::PreHeader, + std::time::Duration::from_millis(3)); + } + Ok::(empty_response()) + }) + .build(); + let mut request = request_builder() + .method(method.clone()) + .uri(path) + .body(Body::empty()) + .expect("should build request"); + if preinstalled { + request.extensions_mut().insert(timings.handle().clone()); + } + let response = + block_on(router.oneshot(request)).expect("should dispatch request"); + assert!( + response.headers().get("server-timing").is_none(), + "attachment should not expose timing" + ); + if preinstalled { + assert_eq!( + timings.snapshot().auction_wait_ms, + Some(3), + "should share handler updates" + ); + assert_eq!( + timings.snapshot().request_elapsed_ms, + None, + "should not fabricate completion" + ); + } + } + } + } + } + #[test] fn sanitize_middleware_strips_configured_trust_headers_before_routing() { let mut settings = settings_with_response_headers(vec![]); diff --git a/crates/trusted-server-adapter-fastly/Cargo.toml b/crates/trusted-server-adapter-fastly/Cargo.toml index 710523766..a8bfff87d 100644 --- a/crates/trusted-server-adapter-fastly/Cargo.toml +++ b/crates/trusted-server-adapter-fastly/Cargo.toml @@ -35,6 +35,7 @@ log-fastly = { workspace = true } serde = { workspace = true } serde_json = { workspace = true } trusted-server-core = { workspace = true } +rand = { workspace = true } url = { workspace = true } urlencoding = { workspace = true } diff --git a/crates/trusted-server-adapter-fastly/src/app.rs b/crates/trusted-server-adapter-fastly/src/app.rs index fbcd5735d..457f6f81d 100644 --- a/crates/trusted-server-adapter-fastly/src/app.rs +++ b/crates/trusted-server-adapter-fastly/src/app.rs @@ -100,6 +100,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::{ @@ -119,6 +120,7 @@ use trusted_server_core::ec::kv::KvIdentityGraph; use trusted_server_core::ec::registry::PartnerRegistry; use trusted_server_core::ec::{EcContext, EidSyncSource}; 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, @@ -140,6 +142,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_STORE_ID, get_settings_from_config_store}; use trusted_server_core::tester_cookie::{handle_clear_tester, handle_set_tester}; @@ -298,6 +301,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 // --------------------------------------------------------------------------- @@ -359,6 +368,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. @@ -414,13 +434,17 @@ 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 = RequestTimings::from_extensions(req.extensions()).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()) { @@ -441,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())) { @@ -493,6 +517,14 @@ 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 = RequestTimings::from_extensions(req.extensions()).unwrap_or_default(); + let _span = state + .registry + .has_request_filters() + .then(|| timings.span(Phase::Filter)); + match state .registry .filter_request(RequestFilterRegistryInput { @@ -526,6 +558,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); @@ -576,7 +609,9 @@ 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 = + RequestTimings::from_extensions(req.extensions()).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), @@ -650,7 +685,8 @@ 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 = RequestTimings::from_extensions(req.extensions()).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, @@ -733,12 +769,14 @@ 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 = RequestTimings::from_extensions(req.extensions()).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 @@ -798,12 +836,32 @@ 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) { + } else if let Some(pattern) = state.registry.matched_route_pattern(&method, &path) { // Integration-proxy responses are not bounded by // publisher.max_buffered_body_bytes. Publisher fallback below uses the // publisher-specific streaming finalizer instead. + // The matched route pattern is an integration-defined literal + // (bounded and content-free by construction), so telemetry keeps it + // verbatim instead of running the request path through the lossy + // publisher classifier. + route_metadata = Some(RouteMetadata { + route_class: RouteClass::IntegrationProxy, + route_template: pattern.to_owned(), + }); state .registry .handle_proxy(ProxyDispatchInput { @@ -831,9 +889,34 @@ 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, + &state.settings.observability.route_sections, + ), + }); + // 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. @@ -899,7 +982,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) } @@ -923,7 +1009,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` @@ -938,6 +1027,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"); @@ -959,6 +1049,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 } @@ -967,6 +1058,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 } @@ -1090,6 +1182,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, } /// Every method an admin route must claim to keep non-primary methods from falling @@ -1112,21 +1208,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, }, // Every method is claimed, not just POST. A method this route did not claim would // fall through to the publisher, and `enforce_basic_auth` leaves the `Authorization` @@ -1136,6 +1236,7 @@ const NAMED_ROUTES: &[NamedRoute] = &[ path: "/_ts/admin/cache/purge", primary_methods: LEGACY_ADMIN_DENY_METHODS, handler: NamedRouteHandler::AdminCachePurge, + route_class: RouteClass::Other, }, // 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. @@ -1143,11 +1244,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. @@ -1155,6 +1258,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 @@ -1166,36 +1270,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. @@ -1203,6 +1314,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 @@ -1213,21 +1325,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", @@ -1236,16 +1356,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 + }) + }) } } @@ -1306,7 +1445,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, + ), ); } @@ -1366,10 +1510,11 @@ mod tests { use super::{ AppState, AuctionDispatch, EcContext, EdgeCacheHeader, EidSyncSource, HandlerFuture, - NAMED_ROUTES, NamedRouteHandler, PAGE_BIDS_LEGACY_PATH, PAGE_BIDS_PATH, RuntimeStoreConfig, - TrustedServerApp, build_orchestrator_with_plan, build_per_request_services, - build_state_from_settings, compile_auction_plan, handle_publisher_request, - publisher_response_into_streaming_response, startup_error_router, + NAMED_ROUTES, NamedRouteHandler, PAGE_BIDS_LEGACY_PATH, PAGE_BIDS_PATH, RouteClass, + RouteMetadata, RuntimeStoreConfig, TSJS_ROUTE_TEMPLATE, TrustedServerApp, + build_orchestrator_with_plan, build_per_request_services, build_state_from_settings, + compile_auction_plan, handle_publisher_request, publisher_response_into_streaming_response, + startup_error_router, }; use base64::Engine as _; use bytes::Bytes; @@ -1379,6 +1524,7 @@ mod tests { use edgezero_core::env_config::EnvConfig; use edgezero_core::http::{ HeaderValue, Method, Request, Response, StatusCode, header, request_builder, + response_builder, }; use edgezero_core::key_value_store::NoopKvStore; use edgezero_core::params::PathParams; @@ -1387,20 +1533,23 @@ mod tests { use error_stack::Report; use futures::executor::block_on; - 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, PlatformTemplateCache, PlatformTemplateCacheReservation, - RuntimeServices, TemplateCacheError, TemplateCacheKey, TemplateCacheLookup, - TemplateCacheMiss, TemplateCacheReservation, TemplateEntry, TemplateMetadata, + ClientInfo, GeoInfo, PlatformBackend, PlatformBackendSpec, PlatformError, PlatformGeo, + PlatformHttpClient, PlatformHttpRequest, PlatformKvStore, PlatformPendingRequest, + PlatformResponse, PlatformSelectResult, PlatformTemplateCache, + PlatformTemplateCacheReservation, RuntimeServices, TemplateCacheError, TemplateCacheKey, + TemplateCacheLookup, TemplateCacheMiss, TemplateCacheReservation, TemplateEntry, + TemplateMetadata, }; + use trusted_server_core::request_timing::RequestTimings; use trusted_server_core::settings::Settings; #[test] @@ -1579,12 +1728,12 @@ 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 plan = Arc::new( trusted_server_core::auction::compile_auction_plan(&settings) @@ -1596,7 +1745,7 @@ mod tests { 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, ), @@ -1604,8 +1753,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 @@ -2291,6 +2447,114 @@ 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, "/integrations/prebid/bundle.js", + "should carry the registered route pattern verbatim, not a classifier output" + ); + } + + #[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, "/other/*", + "the default empty section allowlist should collapse publisher paths" + ); + } + fn browser_request(method: Method, path: &str, fetch_destination: &str) -> Request { let mut request = empty_request(method, path); request.headers_mut().insert( @@ -2731,6 +2995,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 { @@ -3153,6 +3472,7 @@ mod tests { req, asset_route, &effects, + trusted_server_core::geo::GeoLookupState::NotAttempted, )); assert_eq!( @@ -3196,6 +3516,193 @@ 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.handle().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.handle().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" + ); + } + #[test] fn dispatch_runs_request_filter_and_threads_response_effects() { // Regression guard for the EdgeZero request-filter bypass: the publisher @@ -3255,6 +3762,61 @@ mod tests { ); } + /// 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" + ); + } + fn recovery_eligible_of(response: &Response) -> bool { response .extensions() @@ -3298,6 +3860,32 @@ mod tests { ); } + #[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 filter_short_circuit_response_is_not_eligible_for_eid_persistence() { // A request-filter short circuit (e.g. a DataDome challenge/block) must @@ -3335,6 +3923,45 @@ mod tests { ); } + #[test] + fn server_timing_absent_when_no_cache_control_header_exists() { + // The fail-closed case: absence of Cache-Control is not evidence of + // privacy, so emission must be suppressed rather than defaulted on. + let mut response = response_builder() + .body(Body::empty()) + .expect("should build a response with no cache-control header"); + + crate::apply_server_timing_header(&mut response, &RequestTimings::new(), true); + + assert!( + response_header(&response, "server-timing").is_none(), + "should not emit when the response carries no Cache-Control at all" + ); + } + + #[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}" + ); + } + #[test] fn publisher_navigation_origin_start_failure_is_not_recovery_eligible() { // Recovery is authorized only after a successful origin start. With no diff --git a/crates/trusted-server-adapter-fastly/src/main.rs b/crates/trusted-server-adapter-fastly/src/main.rs index b9f3b86be..da3f9dba9 100644 --- a/crates/trusted-server-adapter-fastly/src/main.rs +++ b/crates/trusted-server-adapter-fastly/src/main.rs @@ -1,5 +1,8 @@ use std::sync::Arc; +use rand::Rng as _; +use std::time::{Instant, SystemTime, UNIX_EPOCH}; + use edgezero_adapter_fastly::config_store::FastlyConfigStore as EdgeZeroFastlyConfigStore; use edgezero_adapter_fastly::request::into_core_request; use edgezero_adapter_fastly::runtime_env_config; @@ -13,7 +16,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, cache_control_headers_have_directive}; +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; @@ -22,9 +31,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::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; @@ -364,7 +377,10 @@ fn edgezero_main(mut req: FastlyRequest, sandbox: &mut Sandbox, ordinal: u64, re return; } - let config_store = + let timings = RequestTimings::new(); + + let config_store = { + let _appbuild = timings.span(Phase::AppBuild); match open_trusted_server_config_store(runtime_stores.config_store_name.as_ref()) { Ok(cs) => cs, Err(e) => { @@ -374,8 +390,8 @@ fn edgezero_main(mut req: FastlyRequest, sandbox: &mut Sandbox, ordinal: u64, re .send_to_client(); return; } - }; - + } + }; // Build lazily, once per sandbox. Reached only past the health, JA4, and // counters short-circuits, so none of those pays for construction. // @@ -386,6 +402,7 @@ fn edgezero_main(mut req: FastlyRequest, sandbox: &mut Sandbox, ordinal: u64, re // permanent error mode, and the next callback retries construction. let failed_build = sandbox .initialize(|| { + let _appbuild = timings.span(Phase::AppBuild); let (app, state) = TrustedServerApp::build_app_with_state(&runtime_stores); match state { Some(state) => Ok(RetainedApp { app, state }), @@ -410,6 +427,18 @@ fn edgezero_main(mut req: FastlyRequest, sandbox: &mut Sandbox, ordinal: u64, re let settings_snapshot = app_state.as_ref().map(|state| Arc::clone(&state.settings)); let counters = SandboxCounters::capture(sandbox, ordinal, request_id, settings_snapshot.as_deref()); + let server_timing_enabled = settings_snapshot + .as_deref() + .is_some_and(|settings| settings.observability.server_timing_enabled); + 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("unknown", |settings| settings.publisher.domain.as_str()); let trusted_client_ip = settings_snapshot .as_deref() .and_then(|settings| settings.trusted_client_ip.as_ref()); @@ -429,6 +458,10 @@ fn edgezero_main(mut req: FastlyRequest, sandbox: &mut Sandbox, ordinal: u64, re req.set_header("fastly-ssl", "1"); } + // Capture the method before dispatch consumes the request. The resolved + // client IP is retained below in `ClientInfo`. + let request_method = req.get_method().clone(); + // Strip any client-supplied x-ts-tls-* headers before injecting the trusted // values from the Fastly SDK. Must run after sanitize_fastly_forwarded_headers. req.remove_header("x-ts-tls-protocol"); @@ -460,6 +493,7 @@ fn edgezero_main(mut req: FastlyRequest, sandbox: &mut Sandbox, ordinal: u64, re 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.handle().clone()); match futures::executor::block_on(app.router().oneshot(core_req)) { Ok(response) => response, Err(error) => edge_error_response(error), @@ -478,14 +512,34 @@ fn edgezero_main(mut req: FastlyRequest, sandbox: &mut Sandbox, ordinal: u64, re 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(&runtime_stores) { 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:?}"); @@ -500,14 +554,31 @@ fn edgezero_main(mut req: FastlyRequest, sandbox: &mut Sandbox, ordinal: u64, re if let Some(mut ec_state) = ec_state { if let Some(settings) = settings_snapshot.as_deref() { - match apply_edgezero_ec_finalize(settings, &mut ec_state, &mut response) { + match apply_edgezero_ec_finalize(settings, &mut ec_state, &mut response, &timings) { Ok(partner_registry) => { - send_edgezero_response( + let outcome = send_edgezero_response( response, request_filter_effects.as_ref(), + &SendContext { + timings: timings.clone(), + server_timing_enabled, + method: request_method.as_str(), + publisher_domain, + access_sample_rate, + access_telemetry_enabled, + }, counters.as_ref(), ); - run_edgezero_pull_sync_after_send(settings, &partner_registry, &ec_state); + run_post_send_steps( + || { + run_edgezero_pull_sync_after_send( + settings, + &partner_registry, + &ec_state, + ) + }, + || emit_access_telemetry_after_send(settings, &outcome, &timings), + ); return; } Err(e) => { @@ -519,17 +590,35 @@ fn edgezero_main(mut req: FastlyRequest, sandbox: &mut Sandbox, ordinal: u64, re } else { match load_settings_from_config_store(&runtime_stores) { Ok(settings) => { - match apply_edgezero_ec_finalize(&settings, &mut ec_state, &mut response) { + match apply_edgezero_ec_finalize( + &settings, + &mut ec_state, + &mut response, + &timings, + ) { Ok(partner_registry) => { - send_edgezero_response( + let outcome = send_edgezero_response( response, request_filter_effects.as_ref(), + &SendContext { + timings: timings.clone(), + server_timing_enabled, + method: request_method.as_str(), + publisher_domain, + access_sample_rate, + access_telemetry_enabled, + }, counters.as_ref(), ); - run_edgezero_pull_sync_after_send( - &settings, - &partner_registry, - &ec_state, + run_post_send_steps( + || { + run_edgezero_pull_sync_after_send( + &settings, + &partner_registry, + &ec_state, + ); + }, + || emit_access_telemetry_after_send(&settings, &outcome, &timings), ); return; } @@ -547,7 +636,28 @@ fn edgezero_main(mut req: FastlyRequest, sandbox: &mut Sandbox, ordinal: u64, re } } - send_edgezero_response(response, request_filter_effects.as_ref(), counters.as_ref()); + let outcome = send_edgezero_response( + response, + request_filter_effects.as_ref(), + &SendContext { + timings: timings.clone(), + server_timing_enabled, + method: request_method.as_str(), + publisher_domain, + access_sample_rate, + access_telemetry_enabled, + }, + counters.as_ref(), + ); + // 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. When `app_state` never + // built there is nothing to emit either: `access_telemetry_enabled` was + // necessarily false without a settings snapshot, so the outcome carries + // no access snapshot, and reloading settings here could not change that. + if let Some(settings) = settings_snapshot.as_deref() { + emit_access_telemetry_after_send(settings, &outcome, &timings); + } } fn edge_error_response(error: EdgeError) -> HttpResponse { @@ -575,24 +685,36 @@ 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; + // 401 handling lives in the shared helper. + middleware::write_back_geo_lookup_state(response, geo_info.as_ref()); } fn apply_edgezero_ec_finalize( settings: &Settings, ec_state: &mut 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 }; @@ -653,6 +775,220 @@ where Some((context, kv)) } +/// Runs the post-send steps in their contract order: EC identity pull-sync +/// first, then access-telemetry emission. +/// +/// Every `edgezero_main` site that has both steps routes through this +/// function, so the ordering is owned in exactly one place and the +/// sequence test can instrument it; `request_elapsed` is already stamped +/// before either step because `send_edgezero_response` stamps it before +/// returning. +fn run_post_send_steps(pull_sync: impl FnOnce(), emit_access_telemetry: impl FnOnce()) { + pull_sync(); + emit_access_telemetry(); +} + +/// 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. +/// +/// Sampling happens before snapshot construction, using the same configured +/// rate stored in the row. Disabled and sampled-out requests have no snapshot +/// and return silently. Row construction, send, and non-2xx failures log one +/// warning naming the reason. Credentials were resolved during settings load. +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 or sampled out before + // the response was sent; there is 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); + 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:?}"); + } +} + +/// Per-response context threaded into [`send_edgezero_response`] so the +/// function stays at or under seven parameters. +struct SendContext<'a> { + /// 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: &'a str, + /// The configured publisher domain, borrowed from the settings snapshot. + publisher_domain: &'a str, + /// 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. +pub(crate) struct DeliveryOutcome { + /// Response body size in bytes. + #[allow(dead_code)] + pub bytes: u64, + /// Whether delivery completed or failed partway. Collected as + /// groundwork; not yet emitted on any surface. + #[allow(dead_code)] + pub result: DeliveryResult, + /// Access-telemetry dimensions captured for this response at the + /// freeze point. `None` when access telemetry was disabled or sampled out; + /// 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`]. +/// +/// The `Ok(())` arm exists for the classifier's totality, not for the +/// production caller: `send_edgezero_response` consumes this value only in +/// its `Err` branch and re-derives the success outcome from +/// `streaming_body.finish()`. +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 @@ -661,9 +997,27 @@ where fn send_edgezero_response( mut response: HttpResponse, request_filter_effects: Option<&RequestFilterEffects>, + context: &SendContext, counters: Option<&SandboxCounters>, -) { +) -> 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 = sampled_access_snapshot( + context, + || rand::thread_rng().r#gen::(), + || build_access_telemetry_snapshot(&response, context), + ); // Captured before the body is consumed so post-commitment failures can be // matched back to the response that carried these counters. @@ -689,17 +1043,35 @@ 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() { - // Also post-commitment: same attribution as the - // streaming failure below. + 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{counter_context}: {e}" ); + DeliveryOutcome { + bytes, + result: DeliveryResult::Partial, + snapshot, + } } - } + }, Err(e) => { // After commitment: log and stop. Returning an error here // would let the SDK attempt a second response. Counters @@ -707,15 +1079,118 @@ fn send_edgezero_response( // tagged with the same identity for reconciliation. log::error!("EdgeZero streaming failed{counter_context}: {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, + } + } + } +} + +/// Samples once before doing snapshot work. Neither closure runs when disabled, +/// and sampled-out requests never build dimensions or read environment values. +fn sampled_access_snapshot( + context: &SendContext<'_>, + roll: impl FnOnce() -> f64, + build: impl FnOnce() -> AccessTelemetrySnapshot, +) -> Option { + if !context.access_telemetry_enabled + || !tinybird::sampled_in(context.access_sample_rate, roll()) + { + return None; + } + Some(build()) +} + +/// 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.to_owned(), + status: response.status().as_u16(), + route_class, + route_template, + publisher_domain: context.publisher_domain.to_owned(), + 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, @@ -787,16 +1262,31 @@ 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(), + )) + }) } /// 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> { @@ -809,6 +1299,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())?; @@ -837,12 +1348,18 @@ pub(crate) fn derive_device_signals(req: &FastlyRequest) -> DeviceSignals { #[cfg(test)] mod tests { + use std::sync::Mutex; + 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::time::Duration; use trusted_server_core::integrations::HeaderMutation; + use trusted_server_core::platform::RuntimeServices; + use trusted_server_core::request_timing::AuctionWaitPlacement; fn test_settings() -> Settings { Settings::from_toml( @@ -870,6 +1387,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 pull_sync_noop_states_skip_post_send_graph_factory() { let calls = std::cell::Cell::new(0); @@ -905,6 +1442,21 @@ mod tests { ); } + #[test] + fn health_short_circuit_is_get_only_and_ignores_query() { + for path in ["/health", "/health?probe=1"] { + let url = format!("https://example.com{path}"); + assert!( + health_response(&FastlyRequest::get(&url)).is_some(), + "should bypass GET health" + ); + assert!( + health_response(&FastlyRequest::post(&url)).is_none(), + "should time non-GET health normally" + ); + } + } + #[test] fn health_response_ignores_non_health_paths() { let req = FastlyRequest::get("https://example.com/auction"); @@ -1189,9 +1741,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!( @@ -1257,4 +1810,501 @@ 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 mut 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" + ); + // Returning-user EID persistence is gated on the request source; the + // dispatcher marks document navigations this way before finalization. + ec_context.set_eid_sync_source(trusted_server_core::ec::EidSyncSource::Navigation); + + let mut 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, &mut 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<'static> { + SendContext { + timings: RequestTimings::new(), + server_timing_enabled: false, + method: "GET", + publisher_domain: "publisher.example.com", + access_sample_rate: 0.25, + access_telemetry_enabled: true, + } + } + + #[test] + fn disabled_access_telemetry_skips_entropy_and_snapshot_work() { + let mut context = send_context_fixture(); + context.access_telemetry_enabled = false; + + let snapshot = sampled_access_snapshot( + &context, + || panic!("disabled telemetry should not draw entropy"), + || panic!("disabled telemetry should not construct dimensions"), + ); + + assert!(snapshot.is_none(), "should not build a disabled snapshot"); + } + + #[test] + fn sampled_out_access_telemetry_skips_snapshot_and_transport() { + let context = send_context_fixture(); + let snapshot = sampled_access_snapshot( + &context, + || context.access_sample_rate, + || panic!("sampled-out telemetry should not construct dimensions"), + ); + assert!(snapshot.is_none(), "should exclude the sampling boundary"); + let mut settings = test_settings(); + settings.tinybird.enabled = true; + settings.tinybird.access_enabled = true; + // No resolved token: reaching target construction would panic and a + // transport call would require a registered backend. Neither may run. + settings.tinybird.access_token_secret = None; + emit_access_telemetry_after_send( + &settings, + &DeliveryOutcome { + bytes: 0, + result: DeliveryResult::Complete, + snapshot, + }, + &context.timings, + ); + } + + #[test] + fn sampled_in_snapshot_records_the_exact_rate_and_draws_once() { + let context = send_context_fixture(); + let response = response_builder() + .body(EdgeBody::empty()) + .expect("should build response"); + let draws = std::cell::Cell::new(0); + let builds = std::cell::Cell::new(0); + + let snapshot = sampled_access_snapshot( + &context, + || { + draws.set(draws.get() + 1); + 0.0 + }, + || { + builds.set(builds.get() + 1); + build_access_telemetry_snapshot(&response, &context) + }, + ) + .expect("should include zero entropy at a positive rate"); + + assert_eq!(draws.get(), 1, "should sample exactly once"); + assert_eq!(builds.get(), 1, "should build one sampled snapshot"); + assert_eq!(snapshot.sample_rate, context.access_sample_rate); + } + + #[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, "publisher.example.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 + ); + } + + #[test] + fn post_send_order_is_elapsed_then_pull_sync_then_telemetry() { + // The full contract sequence, instrumented through the real seams: + // `send_edgezero_response` stamps `request_elapsed` before + // returning, and `run_post_send_steps` (which every production + // site with both steps routes through) owns pull-sync-then- + // telemetry ordering. + 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", + publisher_domain: "publisher.example.com", + access_sample_rate: 1.0, + access_telemetry_enabled: true, + }, + None, + ); + assert!( + timings.snapshot().request_elapsed_ms.is_some(), + "request_elapsed should be stamped before any post-send step runs" + ); + assert!( + outcome.snapshot.is_some(), + "the access snapshot should exist for the enabled context" + ); + + let pull_log = Arc::clone(&log); + let emit_log = Arc::clone(&log); + run_post_send_steps( + move || { + pull_log + .lock() + .expect("should lock order log") + .push("pull_sync") + }, + move || { + emit_log + .lock() + .expect("should lock order log") + .push("telemetry") + }, + ); + + assert_eq!( + *log.lock().expect("should lock order log"), + vec!["pull_sync", "telemetry"], + "pull-sync must dispatch before telemetry emits" + ); + } } diff --git a/crates/trusted-server-adapter-fastly/src/middleware.rs b/crates/trusted-server-adapter-fastly/src/middleware.rs index 283f16255..401659fad 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::{ClientInfo, 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"; @@ -71,6 +72,8 @@ impl Middleware for FinalizeResponseMiddleware { || FastlyRequestContext::get(ctx.request()).and_then(|c| c.client_ip), |info| info.client_ip, ); + let timings = + RequestTimings::from_extensions(ctx.request().extensions()).unwrap_or_default(); let mut response = match next.run(ctx).await { Ok(r) => r, @@ -80,13 +83,24 @@ 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 }) }); + // Mirrors the entry-point finalize site in `main.rs` + // (`apply_entry_point_finalize_headers`); 401 handling lives in the + // shared helper. + write_back_geo_lookup_state(&mut response, geo_info.as_ref()); + apply_finalize_headers(&self.settings, geo_info.as_ref(), &mut response); response .headers_mut() @@ -145,14 +159,40 @@ impl Middleware for AuthMiddleware { // Shared geo resolution helper // --------------------------------------------------------------------------- -/// Resolves geo for a response, skipping the lookup for 401 responses. +/// Writes the resolved geo outcome back onto the response as a +/// [`GeoLookupState`] extension, so a downstream access-telemetry snapshot +/// sees what was actually looked up rather than the stale carried-in state. +/// +/// Skips the write on a 401: [`resolve_geo_for_response`] returns `None` +/// for unauthorized responses before consulting the carried state, so +/// writing `Attempted` there would overwrite a carried `Resolved` with a +/// value that was never looked up, and the row would lose a country it +/// legitimately had. +pub(crate) fn write_back_geo_lookup_state(response: &mut Response, geo_info: Option<&GeoInfo>) { + if response.status() == StatusCode::UNAUTHORIZED { + return; + } + let resolved_state = match geo_info { + Some(geo) => GeoLookupState::Resolved(geo.clone()), + None => GeoLookupState::Attempted, + }; + response.extensions_mut().insert(resolved_state); +} + +/// 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 /// @@ -164,6 +204,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 @@ -171,9 +212,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), } } @@ -250,6 +294,51 @@ pub(crate) use trusted_server_core::response_privacy::{ mod tests { use super::*; + #[test] + fn geo_write_back_preserves_resolved_state_on_401() { + // A 401 short-circuits geo resolution before the carried state is + // consulted, so the write-back must not downgrade a carried + // Resolved to Attempted (which would cost the row its country). + let mut response = response_builder() + .status(StatusCode::UNAUTHORIZED) + .body(Body::empty()) + .expect("should build a 401 response"); + response + .extensions_mut() + .insert(GeoLookupState::Resolved(sample_geo_info())); + + write_back_geo_lookup_state(&mut response, None); + + match response.extensions().get::() { + Some(GeoLookupState::Resolved(geo)) => { + assert_eq!( + geo.country, + sample_geo_info().country, + "should keep the carried country" + ); + } + other => panic!("should keep the Resolved state on a 401, got {other:?}"), + } + } + + #[test] + fn geo_write_back_records_attempted_on_non_401_miss() { + let mut response = response_builder() + .status(StatusCode::OK) + .body(Body::empty()) + .expect("should build a 200 response"); + + write_back_geo_lookup_state(&mut response, None); + + assert!( + matches!( + response.extensions().get::(), + Some(GeoLookupState::Attempted) + ), + "should record an attempted-but-missed lookup on ordinary responses" + ); + } + use std::collections::HashMap; use std::net::IpAddr; use std::sync::{Arc, Mutex}; @@ -280,6 +369,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 { @@ -682,6 +784,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![]); @@ -763,6 +926,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 504dbd9fb..b5e3f4100 100644 --- a/crates/trusted-server-adapter-fastly/src/tinybird.rs +++ b/crates/trusted-server-adapter-fastly/src/tinybird.rs @@ -10,10 +10,15 @@ use trusted_server_core::auction::telemetry::{ AuctionEventBatch, AuctionTelemetrySink, NoopAuctionTelemetrySink, }; use trusted_server_core::error::TrustedServerError; -use trusted_server_core::platform::{PlatformBackendSpec, PlatformHttpRequest, RuntimeServices}; +use trusted_server_core::platform::{ + PlatformBackend as _, PlatformBackendSpec, PlatformHttpClient, PlatformHttpRequest, + RuntimeServices, +}; use trusted_server_core::redacted::Redacted; use trusted_server_core::settings::{Settings, TinybirdSettings}; +use crate::platform::FastlyPlatformBackend; + 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); @@ -21,9 +26,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(), )) @@ -39,7 +49,7 @@ struct FastlyTinybirdAuctionTelemetrySink { } #[derive(Debug, Clone)] -struct TinybirdEventsTarget { +pub(crate) struct TinybirdEventsTarget { api_host: String, dataset: String, append_token: Redacted, @@ -63,6 +73,28 @@ 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 and 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, + append_token: config.access_token_secret.expect( + "should contain a resolved Tinybird access token when access telemetry is enabled", + ), + uri, + backend_spec, + max_body_bytes: config.max_body_bytes, + } + } } impl FastlyTinybirdAuctionTelemetrySink { @@ -182,6 +214,131 @@ impl AuctionTelemetrySink for FastlyTinybirdAuctionTelemetrySink { } } +// --------------------------------------------------------------------------- +// Access telemetry: confirmed-delivery emitter +// --------------------------------------------------------------------------- + +/// Decides whether one request's access-telemetry row should be emitted. +/// +/// `roll` is a uniform draw from `[0, 1)`; callers pass +/// `rand::thread_rng().r#gen::()`, which the wasm32-wasip1 guest backs with +/// real WASI randomness (the EC generation path already relies on this and +/// the CI wasm release build verifies it). Comparing the draw directly +/// against `rate` keeps the sampling probability exactly `rate` for every +/// positive value: there is no bucket quantization, so rates below one in a +/// million sample proportionally instead of never, and emitted rows' +/// `sample_rate` matches the probability they were sampled at, which the +/// `sum(1.0 / sample_rate)` volume estimator depends on. +/// +/// `rate <= 0.0` never samples and `rate >= 1.0` always samples, for any +/// `roll` in `[0, 1)`. `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, roll: f64) -> bool { + roll < rate +} + +/// 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 row exceeds the configured request-body limit, 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, + mut row: String, +) -> Result<(), Report> { + // Match the auction sink's NDJSON framing: every row is + // newline-terminated, and the terminator counts toward the body limit. + if !row.ends_with('\n') { + row.push('\n'); + } + let body_len = row.len(); + if body_len > target.max_body_bytes { + return Err(Report::new(TrustedServerError::Proxy { + message: format!( + "Tinybird access telemetry request body has {body_len} bytes, exceeding {} byte limit", + target.max_body_bytes + ), + })); + } + + let auth_header = + FastlyTinybirdAuctionTelemetrySink::authorization_header(target.append_token.expose())?; + 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::debug!( + "sending access telemetry to Tinybird dataset={} host={} backend={}", + target.dataset, + target.api_host, + backend_name + ); + + // The response body is never consumed, so stream it: buffered + // conversion on Fastly materializes the body before the size limit is + // enforced, which a chunked response could abuse. + let response = client + .send(PlatformHttpRequest::new(request, backend_name).with_stream_response()) + .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(), @@ -306,28 +463,33 @@ mod tests { uri: String, headers: Vec<(String, String)>, body: Vec, + stream_response: bool, } + /// 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 stream_response = request.stream_response; let (parts, body) = request.request.into_parts(); let headers = parts .headers @@ -345,11 +507,41 @@ mod tests { uri: parts.uri.to_string(), headers, body: body.into_bytes().unwrap_or_default().to_vec(), + stream_response, }; self.requests .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")) } @@ -431,18 +623,52 @@ mod tests { fn enabled_config() -> TinybirdSettings { TinybirdSettings { enabled: true, + auction_enabled: true, api_host: "api.us-east.aws.tinybird.co".to_owned(), secret_store: None, auction_dataset: "auction_events_raw".to_owned(), auction_token_secret: Some(Redacted::new("append-token".to_owned())), access_enabled: false, access_dataset: "access_logs_raw".to_owned(), - access_token_secret: None, + access_token_secret: Some(Redacted::new("access-append-token".to_owned())), access_sample_rate: 0.0, max_body_bytes: 1024 * 1024, } } + #[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!( @@ -619,6 +845,137 @@ mod tests { ); } + #[test] + fn access_emitter_rejects_oversized_row_before_sending() { + let mut config = enabled_config(); + config.max_body_bytes = 1024; + let target = TinybirdEventsTarget::from_access_config(config); + let http_client = RecordingHttpClient::respond_with(202); + let row = "x".repeat(1025); + + let result = futures::executor::block_on(emit_access_event(&http_client, &target, row)); + + let error = result.expect_err("should reject a row above the configured body limit"); + assert!( + error.to_string().contains("1024"), + "error should name the configured body limit: {error}" + ); + assert!( + http_client + .requests + .lock() + .expect("should lock recorded requests") + .is_empty(), + "should not send an oversized access row" + ); + } + + #[test] + fn access_emitter_posts_ndjson_and_validates_2xx() { + 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 access-append-token") + ); + let body = std::str::from_utf8(&requests[0].body).expect("should record utf8 body"); + assert_eq!( + body, + format!("{row}\n"), + "should send newline-delimited JSON, matching the auction sink's framing" + ); + assert!( + requests[0].stream_response, + "should stream the Tinybird response: the body is never consumed" + ); + } + + #[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.0), + "a 1.0 sample rate should always sample in" + ); + assert!( + sampled_in(1.0, 0.999_999), + "a 1.0 sample rate should sample in for the largest roll" + ); + assert!( + !sampled_in(0.0, 0.0), + "a 0.0 sample rate should never sample in, even on a zero roll" + ); + assert!( + !sampled_in(-1.0, 0.0), + "a negative rate should never sample in" + ); + } + + #[test] + fn sampled_in_keeps_exact_probability_for_tiny_rates() { + // The previous bucket-quantized sampler truncated rates below one + // in a million to a zero threshold, silently emitting nothing. + // Direct comparison keeps every positive rate proportional. + let rate = 0.000_000_1; + assert!( + sampled_in(rate, rate / 2.0), + "a roll below a tiny positive rate should sample in" + ); + assert!( + !sampled_in(rate, rate * 2.0), + "a roll above a tiny positive rate should sample out" + ); + assert!( + !sampled_in(0.000_001_9, 0.000_001_95), + "no downward quantization: the boundary sits exactly at the rate" + ); + assert!( + sampled_in(0.000_001_9, 0.000_001_85), + "rolls just under the rate should sample in" + ); + } + fn header_value<'a>(headers: &'a [(String, String)], name: &str) -> Option<&'a str> { headers .iter() diff --git a/crates/trusted-server-adapter-spin/src/app.rs b/crates/trusted-server-adapter-spin/src/app.rs index b8e8a2492..fb2abca8e 100644 --- a/crates/trusted-server-adapter-spin/src/app.rs +++ b/crates/trusted-server-adapter-spin/src/app.rs @@ -43,6 +43,7 @@ use trusted_server_core::publisher::{ use trusted_server_core::request_signing::{ handle_trusted_server_discovery, handle_verify_signature, }; +use trusted_server_core::request_timing::RequestTimingMiddleware; use trusted_server_core::settings::Settings; #[cfg(all(feature = "spin", target_arch = "wasm32"))] use trusted_server_core::settings_data::{default_config_key, default_secret_store_name}; @@ -886,6 +887,7 @@ fn build_router(state: &Arc) -> RouterService { // any middleware registered ahead of it would observe the // shared-secret authentication header. .middleware(SanitizeRequestMiddleware::new(Arc::clone(&state.settings))) + .middleware(RequestTimingMiddleware::default().with_excluded_paths(&["/health"])) .middleware(FinalizeResponseMiddleware::new(Arc::clone(&state.settings))) .middleware(AuthMiddleware::new(Arc::clone(&state.settings))) // Innermost middleware: normalize every routed request (strip diff --git a/crates/trusted-server-adapter-spin/src/middleware.rs b/crates/trusted-server-adapter-spin/src/middleware.rs index d7a09987a..418d63c88 100644 --- a/crates/trusted-server-adapter-spin/src/middleware.rs +++ b/crates/trusted-server-adapter-spin/src/middleware.rs @@ -55,9 +55,9 @@ impl Middleware for SanitizeRequestMiddleware { /// Spin does not expose geo headers to the application, so /// `X-Geo-Info-Available: false` is emitted for every response. /// -/// Registered directly inside [`SanitizeRequestMiddleware`] and ahead of -/// [`AuthMiddleware`] so that every outgoing response — including auth-rejected -/// ones — carries a consistent set of headers. +/// Registered inside [`RequestTimingMiddleware`](trusted_server_core::request_timing::RequestTimingMiddleware) and ahead of [`AuthMiddleware`] +/// so that every outgoing response — including auth-rejected ones — carries a +/// consistent set of headers. pub struct FinalizeResponseMiddleware { settings: Arc, } @@ -188,6 +188,8 @@ pub(crate) fn apply_finalize_headers( #[cfg(test)] mod tests { use super::*; + use edgezero_core::router::RouterService; + use trusted_server_core::request_timing::{RequestTimingMiddleware, RequestTimings}; use std::collections::HashMap; use std::sync::Mutex; @@ -207,10 +209,10 @@ mod tests { .expect("should build empty test response") } - fn empty_ctx() -> RequestContext { + fn ctx_for_path(path: &str) -> RequestContext { let req = request_builder() .method(Method::GET) - .uri("/test") + .uri(path) .header("x-reader-ip", "198.51.100.7") .header("x-reader-ip-auth", "fictional-shared-secret-0123456789") .body(Body::empty()) @@ -218,6 +220,10 @@ mod tests { RequestContext::new(req, PathParams::new(HashMap::new())) } + fn empty_ctx() -> RequestContext { + ctx_for_path("/test") + } + fn settings_with_response_headers(headers: Vec<(&str, &str)>) -> Settings { // Build from explicit test settings: the settings baked into the // binary contain placeholder secrets that `get_settings()` rejects @@ -316,6 +322,77 @@ mod tests { ); } + #[test] + fn request_timing_middleware_preserves_shared_handle_and_health_policy() { + for method in [Method::GET, Method::POST] { + for path in ["/test", "/health", "/health?probe=1", "/health/child"] { + for preinstalled in [false, true] { + let route_path = path.split('?').next().expect("should have path"); + let expected = preinstalled || route_path != "/health"; + let timings = RequestTimings::new(); + timings.record( + trusted_server_core::request_timing::Phase::Filter, + std::time::Duration::from_millis(7), + ); + std::thread::sleep(std::time::Duration::from_millis(2)); + let router = RouterService::builder() + .middleware( + RequestTimingMiddleware::default().with_excluded_paths(&["/health"]), + ) + .middleware( + RequestTimingMiddleware::default().with_excluded_paths(&["/health"]), + ) + .route(route_path, method.clone(), move |ctx: RequestContext| async move { + let installed = RequestTimings::from_extensions(ctx.request().extensions()); + assert_eq!(installed.is_some(), expected, "should preserve exact health policy"); + if let Some(installed) = installed { + if preinstalled { + assert_eq!(installed.snapshot().filter_ms, Some(7), "should retain upstream facts"); + installed.mark_auction_dispatched(); + assert!(installed.snapshot().auction_dispatched_ms.expect("should mark dispatch") >= 2, + "should retain upstream origin"); + } else { + assert_eq!(installed.snapshot(), trusted_server_core::request_timing::TimingSnapshot::default(), + "should install independent empty facts"); + } + installed.record_auction_wait( + trusted_server_core::request_timing::AuctionWaitPlacement::PreHeader, + std::time::Duration::from_millis(3)); + } + Ok::(empty_response()) + }) + .build(); + let mut request = request_builder() + .method(method.clone()) + .uri(path) + .body(Body::empty()) + .expect("should build request"); + if preinstalled { + request.extensions_mut().insert(timings.handle().clone()); + } + let response = + block_on(router.oneshot(request)).expect("should dispatch request"); + assert!( + response.headers().get("server-timing").is_none(), + "attachment should not expose timing" + ); + if preinstalled { + assert_eq!( + timings.snapshot().auction_wait_ms, + Some(3), + "should share handler updates" + ); + assert_eq!( + timings.snapshot().request_elapsed_ms, + None, + "should not fabricate completion" + ); + } + } + } + } + } + #[test] fn sanitize_middleware_strips_configured_trust_headers_before_routing() { let mut settings = settings_with_response_headers(vec![]); 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..3cf9c693f --- /dev/null +++ b/crates/trusted-server-core/src/access_telemetry.rs @@ -0,0 +1,564 @@ +//! 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}; + +/// 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/auction/endpoints.rs b/crates/trusted-server-core/src/auction/endpoints.rs index ab3585e3d..844fab6de 100644 --- a/crates/trusted-server-core/src/auction/endpoints.rs +++ b/crates/trusted-server-core/src/auction/endpoints.rs @@ -8,7 +8,7 @@ use http::{Request, Response, StatusCode, header}; use serde_json::Value as JsonValue; use crate::auction::formats::AdRequest; -use crate::auction::orchestrator::OrchestrationResult; +use crate::auction::orchestrator::{DispatchAuctionOutcome, OrchestrationResult}; use crate::consent::{consent_allows_server_side_auction, gate_eids_by_consent}; use crate::constants::COOKIE_TS_EIDS; use crate::cookies::extract_cookie_value; @@ -22,6 +22,7 @@ use crate::ec::registry::PartnerRegistry; use crate::error::TrustedServerError; use crate::openrtb::{Eid, Uid}; use crate::platform::RuntimeServices; +use crate::request_timing::RequestTimings; use crate::settings::Settings; use super::AuctionOrchestrator; @@ -145,6 +146,12 @@ pub async fn handle_auction( } let (parts, body) = req.into_parts(); + // T0-anchored timeline (spec section 18). This route is the auction, so + // dispatch and resolve bracket `run_auction` rather than the origin + // fetch, and the commit mark lands once the OpenRTB response carrying the + // targeting has been built. A defaulted handle records into nothing that + // is ever read, so direct-handler tests are unaffected. + let timings = RequestTimings::from_extensions(&parts.extensions).unwrap_or_default(); let body_bytes = body.into_bytes().unwrap_or_default(); if body_bytes.len() > MAX_AUCTION_BODY_SIZE { return Response::builder() @@ -251,6 +258,7 @@ pub async fn handle_auction( &auction_request, ec_context, ); + timings.set_auction_id(observation.auction_id); emit_auction_events_best_effort_lazy(services, || { build_auction_events( observation, @@ -362,10 +370,70 @@ pub async fn handle_auction( ec_context, ); - // Run the auction - let result = match orchestrator.run_auction(&auction_request, &context).await { - Ok(result) => result, - Err(err) => { + timings.set_auction_id(observation.auction_id); + + // Use the split outcome to distinguish real provider work from routing, + // admission, and launch failures. A successful no-bid result alone does not + // prove that dispatch happened. + let (result, provider_launched) = match orchestrator + .dispatch_auction(&auction_request, &context) + .await + { + DispatchAuctionOutcome::Dispatched(dispatched) => { + let provider_launched = dispatched.has_provider_launch(); + if provider_launched { + timings.mark_auction_dispatched(); + } + let result = orchestrator + .collect_dispatched_auction(dispatched, services, &context) + .await; + if provider_launched { + timings.mark_auction_resolved(); + } + (result, provider_launched) + } + DispatchAuctionOutcome::DispatchFailed { + provider_launched, + provider_responses, + fatal_admission_error, + elapsed_ms, + .. + } => { + if provider_launched { + timings.mark_auction_dispatched(); + } + emit_auction_events_best_effort_lazy(services, || { + build_auction_events( + observation, + AuctionTerminalOutcome::ExecutionFailed { + request: Some(&auction_request), + provider_responses: &provider_responses, + reason: "execution_failed", + elapsed_ms, + }, + ) + }) + .await; + let error = fatal_admission_error.unwrap_or_else(|| { + Report::new(TrustedServerError::Auction { + message: "All eligible provider requests failed to dispatch".to_string(), + }) + }); + return Err(error.change_context(TrustedServerError::Auction { + message: "Auction orchestration failed".to_string(), + })); + } + DispatchAuctionOutcome::NotStarted if settings.auction.providers.is_empty() => ( + OrchestrationResult { + provider_responses: Vec::new(), + mediator_response: None, + winning_bids: HashMap::new(), + total_time_ms: 0, + metadata: HashMap::new(), + }, + false, + ), + DispatchAuctionOutcome::NotStarted => { let elapsed_ms = observation.elapsed_ms(); emit_auction_events_best_effort_lazy(services, || { build_auction_events( @@ -379,8 +447,8 @@ pub async fn handle_auction( ) }) .await; - return Err(err.change_context(TrustedServerError::Auction { - message: "Auction orchestration failed".to_string(), + return Err(Report::new(TrustedServerError::Auction { + message: "No planned provider request was started".to_string(), })); } }; @@ -410,6 +478,12 @@ pub async fn handle_auction( } }; + // For this route the response body is the commit, since there is no + // page state to write into. Routing-only results cannot commit an auction. + if provider_launched { + timings.mark_auction_committed(); + } + emit_auction_events_best_effort_lazy(services, || { build_auction_events( observation, @@ -627,10 +701,12 @@ mod tests { use crate::error::IntoHttpResponse as _; use crate::openrtb::Uid; use crate::platform::test_support::{ - NoopBackend, NoopConfigStore, NoopGeo, NoopHttpClient, NoopSecretStore, StubHttpClient, - noop_services, + NoopBackend, NoopConfigStore, NoopGeo, NoopHttpClient, NoopSecretStore, StubBackend, + StubHttpClient, noop_services, + }; + use crate::platform::{ + ClientInfo, PlatformBackend, PlatformHttpClient, PlatformHttpRequest, PlatformResponse, }; - use crate::platform::{ClientInfo, PlatformHttpClient, PlatformHttpRequest, PlatformResponse}; use crate::test_support::tests::{crate_test_settings_str, create_test_settings}; use base64::Engine as _; use base64::engine::general_purpose::STANDARD as BASE64; @@ -658,13 +734,21 @@ mod tests { } fn services_with_telemetry(sink: Arc) -> RuntimeServices { + services_with_http_and_telemetry(Arc::new(NoopHttpClient), Arc::new(NoopBackend), sink) + } + + fn services_with_http_and_telemetry( + http: Arc, + backend: Arc, + sink: Arc, + ) -> RuntimeServices { let telemetry_sink: Arc = sink; RuntimeServices::builder() .config_store(Arc::new(NoopConfigStore)) .secret_store(Arc::new(NoopSecretStore)) .kv_store(Arc::new(edgezero_core::key_value_store::NoopKvStore)) - .backend(Arc::new(NoopBackend)) - .http_client(Arc::new(NoopHttpClient)) + .backend(backend) + .http_client(http) .geo(Arc::new(NoopGeo)) .auction_telemetry_sink(telemetry_sink) .client_info(ClientInfo::default()) @@ -1012,6 +1096,164 @@ mod tests { ); } + #[tokio::test] + async fn planned_endpoint_preserves_installed_collector_across_terminal_states() { + for (provider_configured, transport_failure, metadata_missing) in [ + (true, false, false), + (true, true, false), + (false, false, false), + (true, false, true), + ] { + let provider = if provider_configured { + "[auction.providers.example]\nprotocol = \"openrtb-2.6\"\nprofile = \"standard\"\nendpoint = \"https://bidder.example.com/auction\"\nrouting = \"all_eligible\"\n" + } else { + "" + }; + let settings = Settings::from_toml(&format!( + "{}\n[auction]\nenabled = true\n{provider}", + crate_test_settings_str() + )) + .expect("should parse planned endpoint settings"); + let plan = Arc::new( + crate::auction::compile_auction_plan(&settings) + .expect("should compile endpoint plan"), + ); + let orchestrator = AuctionOrchestrator::from_plan(plan, None); + let http = Arc::new(StubHttpClient::new()); + http.push_response(204, Vec::new()); + if transport_failure { + http.push_select_error(); + } + if metadata_missing { + http.push_pending_backend_name_override(None); + } + let sink = Arc::new(RecordingTelemetrySink::default()); + let services = + services_with_http_and_telemetry(http.clone(), Arc::new(StubBackend), sink.clone()); + let mut ec_context = make_ec_context(Jurisdiction::NonRegulated, None); + let body = json!({ "adUnits": [{ + "code": "example-slot", + "mediaTypes": { "banner": { "sizes": [[300, 250]] } } + }] }); + let mut request = Request::builder() + .method("POST") + .uri("https://publisher.example.com/auction") + .body(EdgeBody::from( + serde_json::to_vec(&body).expect("should serialize endpoint request"), + )) + .expect("should build endpoint request"); + let timings = RequestTimings::new(); + timings.record( + crate::request_timing::Phase::Filter, + std::time::Duration::from_millis(11), + ); + request.extensions_mut().insert(timings.handle().clone()); + + let response = handle_auction( + &settings, + &orchestrator, + None, + None, + &mut ec_context, + &services, + request, + ) + .await; + + if metadata_missing { + assert_eq!( + response + .expect_err("should fail closed after losing pending metadata") + .current_context() + .status_code(), + StatusCode::BAD_GATEWAY + ); + } else { + assert_eq!( + response + .expect("should return a completed or no-bid response") + .status(), + StatusCode::OK, + "should preserve the no-bid HTTP contract" + ); + } + let snapshot = timings.snapshot(); + let auction_id = snapshot + .auction_id + .expect("should record the attempted auction UUID"); + let batches = sink.batches.lock().expect("should lock telemetry batches"); + assert!( + batches[0] + .rows() + .iter() + .all(|row| row.auction_id == auction_id.to_string()), + "should join the original collector to every emitted auction row" + ); + assert_eq!( + snapshot.filter_ms, + Some(11), + "should retain adapter-recorded phases" + ); + assert_eq!( + http.recorded_backend_names().len(), + usize::from(provider_configured), + "should distinguish a real request launch from the empty plan" + ); + if metadata_missing { + assert!( + snapshot.auction_dispatched_ms.is_some(), + "should retain evidence of the request already launched" + ); + assert!( + snapshot.auction_resolved_ms.is_none(), + "should not fabricate collection after dispatch failure" + ); + assert!( + snapshot.auction_committed_ms.is_none(), + "should not commit a failed dispatch" + ); + } else if provider_configured { + let dispatched = snapshot + .auction_dispatched_ms + .expect("should mark a real launch"); + let resolved = snapshot + .auction_resolved_ms + .expect("should mark collection even after transport failure"); + let committed = snapshot + .auction_committed_ms + .expect("should commit the no-bid response"); + assert!( + dispatched <= resolved && resolved <= committed, + "should preserve milestone ordering" + ); + } else { + assert!( + snapshot.auction_dispatched_ms.is_none(), + "should omit zero-launch dispatch" + ); + assert!( + snapshot.auction_resolved_ms.is_none(), + "should omit zero-launch resolution" + ); + assert!( + snapshot.auction_committed_ms.is_none(), + "should omit zero-launch commit" + ); + } + timings.mark_headers_ready(); + timings.mark_request_elapsed(); + assert!( + timings + .handle() + .snapshot( + |inner| inner.headers_ready.is_some() && inner.request_complete.is_some() + ) + .expect("should snapshot original handle"), + "should retain the same collector through response commitment" + ); + } + } + #[tokio::test] async fn all_planned_launch_failures_return_bad_gateway_and_execution_failed_telemetry() { let settings_toml = format!( @@ -1034,13 +1276,15 @@ mod tests { "mediaTypes": { "banner": { "sizes": [[300, 250]] } } }] }); - let request = Request::builder() + let mut request = Request::builder() .method("POST") .uri("https://test-publisher.example/auction") .body(EdgeBody::from( serde_json::to_vec(&body).expect("should serialize launch-failure body"), )) .expect("should build launch-failure request"); + let timings = RequestTimings::new(); + request.extensions_mut().insert(timings.handle().clone()); let error = handle_auction( &settings, @@ -1064,10 +1308,25 @@ mod tests { .expect("should lock telemetry batches"); assert_eq!(batches.len(), 1, "should emit one telemetry batch"); let rows = batches[0].rows(); - assert_eq!(rows.len(), 1, "should emit one execution-failure summary"); - assert_eq!(rows[0].event_kind, "summary"); - assert_eq!(rows[0].terminal_status.as_deref(), Some("execution_failed")); - assert_eq!(rows[0].terminal_reason.as_deref(), Some("execution_failed")); + assert_eq!( + rows.len(), + 2, + "should emit provider failure and summary rows" + ); + let summary = rows + .iter() + .find(|row| row.event_kind == "summary") + .expect("should emit an execution-failure summary"); + assert_eq!(summary.terminal_status.as_deref(), Some("execution_failed")); + assert_eq!(summary.terminal_reason.as_deref(), Some("execution_failed")); + let snapshot = timings.snapshot(); + assert_eq!( + Some(summary.auction_id.clone()), + snapshot.auction_id.map(|id| id.to_string()) + ); + assert!(snapshot.auction_dispatched_ms.is_none()); + assert!(snapshot.auction_resolved_ms.is_none()); + assert!(snapshot.auction_committed_ms.is_none()); } #[tokio::test] @@ -1099,13 +1358,15 @@ mod tests { } ] }); - let req = Request::builder() + let mut req = Request::builder() .method("POST") .uri("https://test-publisher.com/auction") .body(EdgeBody::from( serde_json::to_vec(&body).expect("should serialize body"), )) .expect("should build auction request"); + let timings = RequestTimings::new(); + req.extensions_mut().insert(timings.handle().clone()); let response = handle_auction( &settings, @@ -1146,6 +1407,10 @@ mod tests { assert_eq!(rows[0].event_kind, "summary"); assert_eq!(rows[0].terminal_status.as_deref(), Some("skipped")); assert_eq!(rows[0].terminal_reason.as_deref(), Some("consent_denied")); + let snapshot = timings.snapshot(); + assert_eq!(rows[0].auction_id, snapshot.auction_id.unwrap().to_string()); + assert!(snapshot.auction_dispatched_ms.is_none()); + assert!(snapshot.auction_resolved_ms.is_none()); let ndjson = batches[0] .to_ndjson(16 * 1024) .expect("should serialize telemetry"); diff --git a/crates/trusted-server-core/src/auction/orchestrator.rs b/crates/trusted-server-core/src/auction/orchestrator.rs index 204201e60..5412ab9ff 100644 --- a/crates/trusted-server-core/src/auction/orchestrator.rs +++ b/crates/trusted-server-core/src/auction/orchestrator.rs @@ -16,6 +16,7 @@ use super::openrtb::unused_bidder_params_count; use super::plan::AuctionPlan; use super::provider::{ AuctionProvider, GenericOpenRtbProvider, ProviderParseState, ProviderRequestOutcome, + ProviderRequestStarted, }; #[cfg(test)] use super::routing::RoutedAuction; @@ -33,6 +34,8 @@ use crate::request_signing::RequestSigner; /// TTFB ≈ auction timeout. pub struct DispatchedAuction { pending_requests: Vec, + /// Whether dispatch produced an immediate provider response or started at least one request. + provider_launched: bool, backend_to_provider: HashMap, planned_backend_to_provider: HashMap, completed_responses: Vec, @@ -63,8 +66,10 @@ struct ProviderLaunchState { pub enum DispatchAuctionOutcome { /// No provider request was started and no provider failure was observed. NotStarted, - /// No provider request could be launched, but launch failures were observed. + /// Dispatch failed before collection, possibly after starting a request. DispatchFailed { + /// Whether any provider started a request before dispatch failed. + provider_launched: bool, /// Original auction request. request: AuctionRequest, /// Provider launch-failure responses. @@ -84,6 +89,12 @@ pub enum DispatchAuctionOutcome { } impl DispatchedAuction { + /// Whether at least one provider produced an immediate outcome or started a request. + #[must_use] + pub fn has_provider_launch(&self) -> bool { + self.provider_launched + } + /// Consume the dispatch token without collecting provider responses. #[must_use] pub fn abandon( @@ -122,9 +133,20 @@ impl DispatchedAuction { #[cfg(test)] impl DispatchedAuction { + /// Creates a token with an immediate no-bid outcome for collector tests. + pub(crate) fn immediate_no_bid_for_test(request: AuctionRequest, timeout_ms: u32) -> Self { + let mut dispatched = Self::empty_for_test(request, timeout_ms); + dispatched.provider_launched = true; + dispatched + .completed_responses + .push(AuctionResponse::no_bid("example", 0)); + dispatched + } + pub(crate) fn empty_for_test(request: AuctionRequest, timeout_ms: u32) -> Self { Self { pending_requests: Vec::new(), + provider_launched: false, backend_to_provider: HashMap::new(), planned_backend_to_provider: HashMap::new(), completed_responses: Vec::new(), @@ -1670,6 +1692,7 @@ impl AuctionOrchestrator { .unwrap_or(usize::MAX) }); return DispatchAuctionOutcome::DispatchFailed { + provider_launched: false, request: request.clone(), provider_responses, fatal_admission_error: Some(error), @@ -1693,6 +1716,7 @@ impl AuctionOrchestrator { let mut planned_backend_to_provider = HashMap::new(); let mut reserved_backend_names = HashSet::new(); let mut immediate_response_count = 0usize; + let mut provider_launch_count = 0usize; let mut launch_failure_count = 0usize; for input in routed.inputs() { @@ -1740,6 +1764,7 @@ impl AuctionOrchestrator { request: pending, parse_state, }) => { + provider_launch_count += 1; let Some(backend_name) = pending.backend_name().map(str::to_string) else { launch_failure_count += 1; completed_responses.push(provider_launch_failed_response( @@ -1768,9 +1793,12 @@ impl AuctionOrchestrator { } Ok(ProviderRequestOutcome::Immediate(response)) => { immediate_response_count += 1; + provider_launch_count += 1; completed_responses.push(response); } Err(error) => { + provider_launch_count += + usize::from(error.contains::()); log::warn!( "Planned provider '{}' failed to dispatch: {error:?}", provider.provider_name() @@ -1802,6 +1830,7 @@ impl AuctionOrchestrator { .unwrap_or(usize::MAX) }); return DispatchAuctionOutcome::DispatchFailed { + provider_launched: provider_launch_count > 0, request: request.clone(), provider_responses: completed_responses, fatal_admission_error: None, @@ -1815,6 +1844,7 @@ impl AuctionOrchestrator { } DispatchAuctionOutcome::Dispatched(DispatchedAuction { + provider_launched: provider_launch_count > 0, pending_requests, backend_to_provider: HashMap::new(), planned_backend_to_provider, @@ -1901,8 +1931,12 @@ impl AuctionOrchestrator { let completed_responses: Vec = Vec::new(); #[cfg(test)] let mut immediate_response_count = 0usize; + #[cfg(test)] + let mut provider_launch_count = 0usize; #[cfg(not(test))] let immediate_response_count = 0usize; + #[cfg(not(test))] + let provider_launch_count = 0usize; #[cfg(test)] for provider_name in &provider_names { @@ -1973,6 +2007,10 @@ impl AuctionOrchestrator { request: pending, parse_state, }) => { + #[cfg(test)] + { + provider_launch_count += 1; + } let backend_name = pending.backend_name().map(str::to_string).or_else(|| { if let Some(backend_name) = predicted_backend_name.as_ref() { log::warn!( @@ -2027,9 +2065,14 @@ impl AuctionOrchestrator { } Ok(ProviderRequestOutcome::Immediate(response)) => { immediate_response_count += 1; + #[cfg(test)] + { + provider_launch_count += 1; + } completed_responses.push(response); } Err(e) => { + provider_launch_count += usize::from(e.contains::()); let response_time_ms = start_time.elapsed().as_millis() as u64; log::warn!( "Provider '{}' failed to dispatch request: {:?}", @@ -2049,6 +2092,7 @@ impl AuctionOrchestrator { DispatchAuctionOutcome::NotStarted } else { DispatchAuctionOutcome::DispatchFailed { + provider_launched: provider_launch_count > 0, request: request.clone(), provider_responses: completed_responses, fatal_admission_error: None, @@ -2067,6 +2111,7 @@ impl AuctionOrchestrator { ); DispatchAuctionOutcome::Dispatched(DispatchedAuction { + provider_launched: provider_launch_count > 0, pending_requests, backend_to_provider, planned_backend_to_provider: HashMap::new(), @@ -2100,6 +2145,7 @@ impl AuctionOrchestrator { ) -> OrchestrationResult { let DispatchedAuction { pending_requests, + provider_launched: _, mut backend_to_provider, mut planned_backend_to_provider, completed_responses, @@ -2972,6 +3018,10 @@ mod tests { else { panic!("all-skipped auction should produce a completed dispatch token"); }; + assert!( + !dispatched.has_provider_launch(), + "routing-only skipped outcomes must not claim a provider launch" + ); orchestrator .collect_dispatched_auction(dispatched, &services, &context) .await diff --git a/crates/trusted-server-core/src/auction/provider.rs b/crates/trusted-server-core/src/auction/provider.rs index 62b2ddc8f..10caabb77 100644 --- a/crates/trusted-server-core/src/auction/provider.rs +++ b/crates/trusted-server-core/src/auction/provider.rs @@ -29,6 +29,10 @@ use super::types::{AuctionContext, AuctionRequest, AuctionResponse}; const MAX_PLANNED_RESPONSE_BYTES: usize = 1024 * 1024; +/// Evidence attached when bookkeeping fails after the platform started a request. +#[derive(Debug)] +pub(crate) struct ProviderRequestStarted; + fn attach_provider_routing_metadata( response: &mut AuctionResponse, profile: &CompiledOpenRtbProfile, @@ -392,7 +396,8 @@ impl GenericOpenRtbProvider { "Provider {} pending request backend did not match registered backend", self.provider_name() ), - })); + }) + .attach_opaque(ProviderRequestStarted)); } let parse_state = match &self.plan.profile { CompiledOpenRtbProfile::Standard(_) => GenericOpenRtbParseState::Standard { diff --git a/crates/trusted-server-core/src/config.rs b/crates/trusted-server-core/src/config.rs index 79f100e2f..6accb537b 100644 --- a/crates/trusted-server-core/src/config.rs +++ b/crates/trusted-server-core/src/config.rs @@ -182,6 +182,10 @@ impl edgezero_core::app_config::AppConfigMeta for TrustedServerAppConfig { vec![optional_object("tinybird"), object("auction_token_secret")], true, ), + field( + vec![optional_object("tinybird"), object("access_token_secret")], + true, + ), field( vec![ optional_object("integrations"), @@ -421,7 +425,7 @@ fn validate_secret_key_references(settings: &Settings) -> Result<(), Report Result<(), Report("datadome")? { if datadome.enable_protection { let key = datadome @@ -830,6 +843,7 @@ formats = [{ width = 300, height = 250 }] ("handlers[*].password".to_owned(), false), ("trusted_client_ip.shared_secret".to_owned(), false), ("tinybird.auction_token_secret".to_owned(), true), + ("tinybird.access_token_secret".to_owned(), true), ( "integrations.datadome.server_side_key_secret_name".to_owned(), true, diff --git a/crates/trusted-server-core/src/config_payload.rs b/crates/trusted-server-core/src/config_payload.rs index c9690b01f..9ca340b25 100644 --- a/crates/trusted-server-core/src/config_payload.rs +++ b/crates/trusted-server-core/src/config_payload.rs @@ -72,16 +72,26 @@ pub fn settings_from_config_blob( } fn remove_inactive_secret_references(data: &mut serde_json::Value) { - if data - .pointer("/tinybird/enabled") - .and_then(serde_json::Value::as_bool) - != Some(true) - && let Some(tinybird) = data - .get_mut("tinybird") - .and_then(serde_json::Value::as_object_mut) + if let Some(tinybird) = data + .get_mut("tinybird") + .and_then(serde_json::Value::as_object_mut) { - tinybird.remove("auction_token_secret"); - tinybird.remove("access_token_secret"); + let master_enabled = + tinybird.get("enabled").and_then(serde_json::Value::as_bool) == Some(true); + let auction_enabled = tinybird + .get("auction_enabled") + .and_then(serde_json::Value::as_bool) + .unwrap_or(true); + let access_enabled = tinybird + .get("access_enabled") + .and_then(serde_json::Value::as_bool) + == Some(true); + if !master_enabled || !auction_enabled { + tinybird.remove("auction_token_secret"); + } + if !master_enabled || !access_enabled { + tinybird.remove("access_token_secret"); + } } if let Some(partners) = data @@ -631,6 +641,92 @@ mod tests { assert!(error.to_string().contains("ec.partners[0].ts_pull_token")); } + #[test] + fn inactive_tinybird_sinks_strip_stale_secret_references_before_resolution() { + let mut original = test_settings(); + let mut data = serde_json::to_value(&original).expect("should serialize settings"); + data["tinybird"] = serde_json::json!({ + "enabled": false, + "auction_token_secret": "unused-auction-token", + "access_token_secret": "unused-access-token", + }); + let envelope = BlobEnvelope::new(data, "2026-01-01T00:00:00Z".to_owned()); + let envelope_json = serde_json::to_string(&envelope).expect("should serialize envelope"); + + let loaded = settings_from_config_blob( + &envelope_json, + &UnifiedSecretStore, + &StoreName::from("ts_secrets"), + ) + .expect("should ignore stale secrets for disabled sinks"); + assert!(!loaded.tinybird.enabled); + assert!(loaded.tinybird.auction_enabled, "auction defaults on"); + assert!(!loaded.tinybird.access_enabled, "access defaults off"); + assert!(loaded.tinybird.auction_token_secret.is_none()); + assert!(loaded.tinybird.access_token_secret.is_none()); + + let mut data = serde_json::to_value(&original).expect("should serialize settings"); + data["tinybird"] = serde_json::json!({ + "enabled": true, + "api_host": "api.example.com", + "auction_enabled": false, + "auction_token_secret": "unused-auction-token", + "access_enabled": true, + "access_token_secret": "tinybird-token-key", + "access_sample_rate": 1.0, + }); + let envelope = BlobEnvelope::new(data, "2026-01-01T00:00:00Z".to_owned()); + let envelope_json = serde_json::to_string(&envelope).expect("should serialize envelope"); + let loaded = settings_from_config_blob( + &envelope_json, + &UnifiedSecretStore, + &StoreName::from("ts_secrets"), + ) + .expect("should load active access telemetry without the disabled auction token"); + assert!(!loaded.tinybird.auction_enabled); + assert!(loaded.tinybird.auction_token_secret.is_none()); + assert_eq!( + loaded + .tinybird + .access_token_secret + .as_ref() + .map(Redacted::expose) + .map(String::as_str), + Some("resolved-tinybird-token") + ); + + let mut data = serde_json::to_value(&original).expect("should serialize settings"); + data["tinybird"] = serde_json::json!({ + "enabled": true, + "api_host": "api.example.com", + "auction_token_secret": "tinybird-token-key", + "access_token_secret": "unused-access-token", + }); + let envelope = BlobEnvelope::new(data, "2026-01-01T00:00:00Z".to_owned()); + let envelope_json = serde_json::to_string(&envelope).expect("should serialize envelope"); + let loaded = settings_from_config_blob( + &envelope_json, + &UnifiedSecretStore, + &StoreName::from("ts_secrets"), + ) + .expect("should load the default-on auction sink without the disabled access token"); + assert!(loaded.tinybird.auction_enabled, "auction defaults on"); + assert!(!loaded.tinybird.access_enabled, "access defaults off"); + assert!(loaded.tinybird.access_token_secret.is_none()); + assert!(loaded.tinybird.auction_token_secret.is_some()); + + original.tinybird.enabled = true; + original.tinybird.api_host = "api.example.com".to_owned(); + original.tinybird.auction_token_secret = None; + let error = settings_from_config_blob( + &self::envelope_json(&original), + &UnifiedSecretStore, + &StoreName::from("ts_secrets"), + ) + .expect_err("should reject a missing active default-on auction token"); + assert!(error.to_string().contains("tinybird.auction_token_secret")); + } + #[test] fn inactive_optional_features_do_not_resolve_stale_secret_references() { let mut original = test_settings(); diff --git a/crates/trusted-server-core/src/constants.rs b/crates/trusted-server-core/src/constants.rs index 1b55679e2..8e39f2d19 100644 --- a/crates/trusted-server-core/src/constants.rs +++ b/crates/trusted-server-core/src/constants.rs @@ -38,6 +38,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 b0eb83d3f..8653f2342 100644 --- a/crates/trusted-server-core/src/ec/kv.rs +++ b/crates/trusted-server-core/src/ec/kv.rs @@ -1717,6 +1717,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/gpt_bootstrap.js b/crates/trusted-server-core/src/integrations/gpt_bootstrap.js index afae77535..0c2f00133 100644 --- a/crates/trusted-server-core/src/integrations/gpt_bootstrap.js +++ b/crates/trusted-server-core/src/integrations/gpt_bootstrap.js @@ -326,7 +326,7 @@ // and deliberately identical to the bundle scheduler — the impression is // spent on a viewed tab, and the post-hydration guarantee holds whenever // the request is actually issued. - ts.scheduleInitialAdInit = function (initialBids, initialSlots) { + ts.scheduleInitialAdInit = function (initialBids, initialSlots, initialAuctionDiagnostics) { // The bundle may replace this scheduler after the fallback claims the initial // pass. Keep the latch on the shared document API so replacement cannot reset it. if ((ts.navGeneration || 0) !== 0 || ts.initialAdInitScheduled) return; @@ -336,6 +336,9 @@ // would overwrite a committed SPA navigation's slots. if (initialSlots !== undefined) ts.adSlots = initialSlots; if (initialBids !== undefined) ts.bids = initialBids; + if (initialAuctionDiagnostics !== undefined) { + ts.auctionDiagnostics = initialAuctionDiagnostics; + } var fire = function () { if ((ts.navGeneration || 0) !== 0) return; if (typeof ts.adInit === "function") ts.adInit(); diff --git a/crates/trusted-server-core/src/integrations/gpt_diagnostics.rs b/crates/trusted-server-core/src/integrations/gpt_diagnostics.rs index 1447a8358..de1aedd36 100644 --- a/crates/trusted-server-core/src/integrations/gpt_diagnostics.rs +++ b/crates/trusted-server-core/src/integrations/gpt_diagnostics.rs @@ -62,6 +62,7 @@ pub enum GptDiagnosticsCookieAction { #[derive(Clone, Debug, Default, PartialEq, Eq)] pub struct GptDiagnosticsRequestDecision { active: bool, + browser_session_active: bool, clean_browser_path_and_query: Option, cookie_action: GptDiagnosticsCookieAction, } @@ -73,6 +74,16 @@ impl GptDiagnosticsRequestDecision { self.active } + /// Whether this request came from an activated diagnostics browser session. + /// + /// Unlike [`Self::active`], this remains true for non-document requests such + /// as the SPA page-bids fetch. It is captured before the private activation + /// cookie is stripped from the request. + #[must_use] + pub(crate) fn browser_session_active(&self) -> bool { + self.browser_session_active + } + /// Whether the response must be private and non-storeable. #[must_use] pub fn requires_private_no_store(&self) -> bool { @@ -121,6 +132,7 @@ impl GptDiagnosticsRequestDecision { pub(crate) fn active_for_tests() -> Self { Self { active: true, + browser_session_active: true, clean_browser_path_and_query: None, cookie_action: GptDiagnosticsCookieAction::None, } @@ -143,6 +155,7 @@ mod head_seam_invariant_tests { ] { out.push(GptDiagnosticsRequestDecision { active, + browser_session_active: active, clean_browser_path_and_query: clean.clone(), cookie_action, }); @@ -279,12 +292,19 @@ pub fn prepare_request( replace_path_and_query(request, &clean_path)?; } - let mut decision = GptDiagnosticsRequestDecision::default(); + let mut decision = GptDiagnosticsRequestDecision { + browser_session_active: integration_enabled + && directive == QueryDirective::Absent + && cookie_state.occurrences == 1 + && cookie_state.canonical, + ..GptDiagnosticsRequestDecision::default() + }; if integration_enabled && eligible_navigation && had_reserved_query { decision.clean_browser_path_and_query = Some(clean_path); match directive { QueryDirective::Enable => { decision.active = true; + decision.browser_session_active = true; decision.cookie_action = GptDiagnosticsCookieAction::SetSession; } QueryDirective::Disable => { @@ -547,6 +567,22 @@ mod tests { assert_eq!(duplicate.headers()[header::COOKIE], "other=value"); } + #[test] + fn active_cookie_marks_non_document_requests_without_activating_document_behavior() { + let mut request = Request::builder() + .method(Method::GET) + .uri("https://publisher.example/_ts/page-bids?path=/article") + .header(header::COOKIE, "__Host-ts-console=1; other=value") + .body(EdgeBody::empty()) + .expect("should build page-bids request"); + + let decision = prepare_request(&settings(true), &mut request).expect("should prepare"); + + assert!(!decision.active()); + assert!(decision.browser_session_active()); + assert_eq!(request.headers()[header::COOKIE], "other=value"); + } + #[test] fn invalid_duplicate_and_disable_directives_fail_closed() { for query in [ diff --git a/crates/trusted-server-core/src/integrations/registry.rs b/crates/trusted-server-core/src/integrations/registry.rs index d3c09cd7d..8d2195bec 100644 --- a/crates/trusted-server-core/src/integrations/registry.rs +++ b/crates/trusted-server-core/src/integrations/registry.rs @@ -723,7 +723,17 @@ impl IntegrationRegistrationBuilder { } } -type RouteValue = (Arc, &'static str); +/// Proxy handler, integration id, and the registered route pattern (kept so +/// telemetry can label responses with the integration-defined literal, e.g. +/// `/integrations/prebid/*`, instead of deriving anything from the request +/// path). +type RouteValue = (Arc, &'static str, String); + +/// A test-constructor route entry: method, path pattern, and the proxy with +/// its integration id ([`IntegrationRegistry::from_routes`] fills the +/// pattern into [`RouteValue`] itself). +#[cfg(test)] +type RouteEntry<'a> = (Method, &'a str, (Arc, &'static str)); struct IntegrationRegistryInner { // Method-specific routers for O(log n) lookups @@ -869,7 +879,11 @@ impl IntegrationRegistry { for proxy in registration.proxies { for route in proxy.routes() { - let value = (proxy.clone(), registration.integration_id); + let value = ( + proxy.clone(), + registration.integration_id, + route.path.clone(), + ); // Convert /* wildcard to matchit's {*rest} syntax let matchit_path = if route.path.ends_with("/*") { @@ -966,6 +980,27 @@ impl IntegrationRegistry { self.find_route(method, path).is_some() } + /// The registered route pattern matched by `method` and `path`, if any. + /// + /// Patterns are integration-defined literals (for example + /// `/integrations/prebid/*`), so they are bounded and content-free and + /// safe to store as a telemetry dimension, unlike the request path. + #[must_use] + pub fn matched_route_pattern(&self, method: &Method, path: &str) -> Option<&str> { + self.find_route(method, path).map(|value| value.2.as_str()) + } + + /// 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 @@ -1041,7 +1076,7 @@ impl IntegrationRegistry { services, mut req, } = input; - if let Some((proxy, _)) = self.find_route(method, path) { + if let Some((proxy, _, _)) = self.find_route(method, path) { // Organic proxy handler: generate if needed (best effort). // Only generate for document navigations — subresource requests // may lack consent signals such as the Sec-GPC header. @@ -1354,7 +1389,7 @@ impl IntegrationRegistry { /// # Panics /// /// Panics if route registration fails due to duplicate or invalid paths. - pub fn from_routes(routes: Vec<(Method, &str, RouteValue)>) -> Self { + pub fn from_routes(routes: Vec>) -> Self { let mut get_router = Router::new(); let mut post_router = Router::new(); let mut put_router = Router::new(); @@ -1363,7 +1398,8 @@ impl IntegrationRegistry { let mut head_router = Router::new(); let mut options_router = Router::new(); - for (method, path, value) in routes { + for (method, path, (proxy, integration_id)) in routes { + let value: RouteValue = (proxy, integration_id, path.to_owned()); // Convert /* wildcard to matchit's {*rest} syntax let matchit_path = if path.ends_with("/*") { format!( diff --git a/crates/trusted-server-core/src/lib.rs b/crates/trusted-server-core/src/lib.rs index 249f741ab..3083a95eb 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; @@ -62,6 +63,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 63f5c2a94..2802bd3e5 100644 --- a/crates/trusted-server-core/src/platform/mod.rs +++ b/crates/trusted-server-core/src/platform/mod.rs @@ -43,6 +43,7 @@ mod template_assembly; mod template_cache; #[cfg(test)] pub(crate) mod test_support; +mod timed_kv; mod traits; mod types; @@ -72,6 +73,7 @@ pub use template_cache::{ TemplateCookieValue, TemplateEntry, TemplateMetadata, TemplateMetadataEncodeError, UnavailableTemplateCache, VaryHeaderValues, VarySpec, reader_url_surrogate_key, }; +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..0157f26f2 --- /dev/null +++ b/crates/trusted-server-core/src/platform/timed_kv.rs @@ -0,0 +1,123 @@ +//! Latency-only timing decorator for Edge Cookie KV store handles. +//! +//! [`TimedKvStore`] wraps an [`EcKvStore`] plus a [`RequestTimings`] handle and +//! records [`Phase::EcKv`] around every store call at +//! [`KvIdentityGraph`](crate::ec::kv::KvIdentityGraph) construction sites. +//! The decorator measures latency only: it never reads, parses, or logs values. + +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 } + } +} + +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 key_exists(&self, key: &str) -> Result> { + let _span = self.timings.span(Phase::EcKv); + self.inner.key_exists(key) + } + + fn insert( + &self, + key: &str, + write: EcKvWrite<'_>, + ) -> Result> { + let _span = self.timings.span(Phase::EcKv); + self.inner.insert(key, write) + } + + fn list_keys_with_prefix( + &self, + prefix: &str, + limit: u32, + ) -> Result, Report> { + let _span = self.timings.span(Phase::EcKv); + self.inner.list_keys_with_prefix(prefix, limit) + } + + 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; + + 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: Duration::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" + ); + } +} diff --git a/crates/trusted-server-core/src/publisher.rs b/crates/trusted-server-core/src/publisher.rs index d8c217076..4a1775d3c 100644 --- a/crates/trusted-server-core/src/publisher.rs +++ b/crates/trusted-server-core/src/publisher.rs @@ -22,7 +22,8 @@ use std::borrow::Cow; use std::io::Write; use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::{Arc, Mutex}; -use std::time::{Duration, Instant, SystemTime}; +use std::time::{Duration, SystemTime}; +use web_time::Instant; use brotli::Decompressor; use brotli::enc::BrotliEncoderParams; @@ -43,7 +44,7 @@ use crate::auction::formats::sanitize_publisher_page_url; use crate::auction::orchestrator::{ AuctionOrchestrator, DispatchAuctionOutcome, DispatchedAuction, ERROR_TYPE_ALL, ERROR_TYPE_HTTP_STATUS, ERROR_TYPE_LAUNCH_FAILED, ERROR_TYPE_PARSE_RESPONSE, - ERROR_TYPE_TIMEOUT, ERROR_TYPE_TRANSPORT, + ERROR_TYPE_TIMEOUT, ERROR_TYPE_TRANSPORT, OrchestrationResult, }; use crate::auction::telemetry::{ AuctionObservationContext, AuctionSource, AuctionTerminalOutcome, build_auction_events, @@ -76,6 +77,7 @@ use crate::platform::{ reader_url_surrogate_key, }; 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, @@ -98,21 +100,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", @@ -135,6 +160,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)] @@ -1729,6 +1755,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 @@ -1972,6 +2004,8 @@ pub async fn buffer_publisher_response_async( ¶ms.request_scheme, ¶ms.request_host, ), + timings: params.timings.clone(), + placement: AuctionWaitPlacement::PreHeader, }, ) .await; @@ -2138,6 +2172,7 @@ fn build_template_assembly_params( request_scheme: &str, price_granularity: PriceGranularity, ad_bids_state: AdBidsState, + timings: RequestTimings, ) -> OwnedProcessResponseParams { OwnedProcessResponseParams { csp_nonce_observed: None, @@ -2160,6 +2195,7 @@ fn build_template_assembly_params( price_granularity, gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings, } } @@ -2502,6 +2538,8 @@ pub async fn publisher_response_into_streaming_response( ¶ms.request_scheme, ¶ms.request_host, ), + timings: params.timings.clone(), + placement: AuctionWaitPlacement::InStream, }, ) .await; @@ -2620,6 +2658,7 @@ pub async fn publisher_response_into_streaming_response( &orchestrator, &services, &settings, + AuctionWaitPlacement::InStream, ) .await; // Collection reached a terminal result; disarm only now @@ -2645,6 +2684,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( @@ -2989,6 +3030,7 @@ pub async fn stream_publisher_body_async( orchestrator, services, settings, + AuctionWaitPlacement::PreHeader, ) .await; if body.is_stream() { @@ -3063,6 +3105,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, }, }, ) @@ -3248,6 +3292,44 @@ fn request_origin(scheme: &str, host: &str) -> String { /// JSON for every non-empty map; `serde_json::from_str` failed and `unwrap_or_default()` /// turned the failure into `{}`. Shared modes therefore served **zero bids**, silently, /// on every request that had any. Every fixture had empty bids, so nothing caught it. +#[derive(Clone, Debug, serde::Serialize)] +#[serde(rename_all = "camelCase")] +struct BrowserAuctionDiagnostics { + #[serde(skip_serializing_if = "Option::is_none")] + auction_dispatched_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + auction_resolved_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + auction_committed_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + auction_wait_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + auction_wait_placement: Option<&'static str>, +} + +const fn auction_wait_placement_wire(placement: AuctionWaitPlacement) -> &'static str { + match placement { + AuctionWaitPlacement::PreHeader => "pre_header", + AuctionWaitPlacement::InStream => "in_stream", + } +} + +impl BrowserAuctionDiagnostics { + fn from_request_timings(timings: &RequestTimings) -> Option { + let snapshot = timings.snapshot(); + snapshot.auction_dispatched_ms?; + Some(Self { + auction_dispatched_ms: snapshot.auction_dispatched_ms, + auction_resolved_ms: snapshot.auction_resolved_ms, + auction_committed_ms: snapshot.auction_committed_ms, + auction_wait_ms: snapshot.auction_wait_ms, + auction_wait_placement: snapshot + .auction_wait_placement + .map(auction_wait_placement_wire), + }) + } +} + #[derive(Clone, Default)] pub(crate) struct AdBidsState { /// Rendered bids `` sequences inside the string. pub(crate) fn build_bids_script(bid_map: &serde_json::Map) -> String { + build_bids_script_with_diagnostics(bid_map, None) +} + +fn build_bids_script_with_diagnostics( + bid_map: &serde_json::Map, + auction_diagnostics: Option<&BrowserAuctionDiagnostics>, +) -> String { let json = serde_json::to_string(bid_map) .expect("serde_json::to_string of Map should be infallible"); let escaped = html_escape_for_script(&json); @@ -5968,6 +6191,23 @@ pub(crate) fn build_bids_script(bid_map: &serde_json::Map(function(){{\ +var t=window.tsjs=window.tsjs||{{}};\ +var b=JSON.parse(\"{}\");\ +var d=JSON.parse(\"{}\");\ +var s=t.scheduleInitialAdInit;\ +if(typeof s===\"function\")s(b,void 0,d);\ +else{{t.bids=b;t.auctionDiagnostics=d;}}\ +}})();", + escaped, + html_escape_for_script(&diagnostics) + ); + } + format!( "", + html_escape_for_script(slots_json), + html_escape_for_script(&bids), + html_escape_for_script(&diagnostics) + ); + } + format!( "