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 679c9dd4f..8c4807281 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1428,15 +1428,19 @@ dependencies = [ [[package]] name = "edgezero-adapter" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?tag=v0.0.8#567964158e4f8bd0d52321b9801de44966422e1b" +source = "git+https://github.com/stackpop/edgezero?rev=12c3215c2637d961a27eefa12e235033fadb4c4a#12c3215c2637d961a27eefa12e235033fadb4c4a" dependencies = [ + "serde", + "serde_json", + "sha2 0.10.9", "toml", + "walkdir", ] [[package]] name = "edgezero-adapter-axum" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?tag=v0.0.8#567964158e4f8bd0d52321b9801de44966422e1b" +source = "git+https://github.com/stackpop/edgezero?rev=12c3215c2637d961a27eefa12e235033fadb4c4a#12c3215c2637d961a27eefa12e235033fadb4c4a" dependencies = [ "anyhow", "async-trait", @@ -1464,7 +1468,7 @@ dependencies = [ [[package]] name = "edgezero-adapter-cloudflare" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?tag=v0.0.8#567964158e4f8bd0d52321b9801de44966422e1b" +source = "git+https://github.com/stackpop/edgezero?rev=12c3215c2637d961a27eefa12e235033fadb4c4a#12c3215c2637d961a27eefa12e235033fadb4c4a" dependencies = [ "anyhow", "async-trait", @@ -1487,7 +1491,7 @@ dependencies = [ [[package]] name = "edgezero-adapter-fastly" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?tag=v0.0.8#567964158e4f8bd0d52321b9801de44966422e1b" +source = "git+https://github.com/stackpop/edgezero?rev=12c3215c2637d961a27eefa12e235033fadb4c4a#12c3215c2637d961a27eefa12e235033fadb4c4a" dependencies = [ "anyhow", "async-stream", @@ -1516,7 +1520,7 @@ dependencies = [ [[package]] name = "edgezero-adapter-spin" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?tag=v0.0.8#567964158e4f8bd0d52321b9801de44966422e1b" +source = "git+https://github.com/stackpop/edgezero?rev=12c3215c2637d961a27eefa12e235033fadb4c4a#12c3215c2637d961a27eefa12e235033fadb4c4a" dependencies = [ "anyhow", "async-trait", @@ -1543,7 +1547,7 @@ dependencies = [ [[package]] name = "edgezero-cli" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?tag=v0.0.8#567964158e4f8bd0d52321b9801de44966422e1b" +source = "git+https://github.com/stackpop/edgezero?rev=12c3215c2637d961a27eefa12e235033fadb4c4a#12c3215c2637d961a27eefa12e235033fadb4c4a" dependencies = [ "chrono", "clap", @@ -1568,7 +1572,7 @@ dependencies = [ [[package]] name = "edgezero-core" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?tag=v0.0.8#567964158e4f8bd0d52321b9801de44966422e1b" +source = "git+https://github.com/stackpop/edgezero?rev=12c3215c2637d961a27eefa12e235033fadb4c4a#12c3215c2637d961a27eefa12e235033fadb4c4a" dependencies = [ "anyhow", "async-compression", @@ -1599,7 +1603,7 @@ dependencies = [ [[package]] name = "edgezero-macros" version = "0.1.0" -source = "git+https://github.com/stackpop/edgezero?tag=v0.0.8#567964158e4f8bd0d52321b9801de44966422e1b" +source = "git+https://github.com/stackpop/edgezero?rev=12c3215c2637d961a27eefa12e235033fadb4c4a#12c3215c2637d961a27eefa12e235033fadb4c4a" dependencies = [ "log", "proc-macro2", @@ -5438,6 +5442,7 @@ dependencies = [ "futures", "log", "log-fastly", + "rand 0.8.6", "serde", "serde_json", "toml", diff --git a/Cargo.toml b/Cargo.toml index 51e3038ea..6a197f14a 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -55,12 +55,12 @@ 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", tag = "v0.0.8", default-features = false } -edgezero-adapter-cloudflare = { git = "https://github.com/stackpop/edgezero", tag = "v0.0.8", default-features = false } -edgezero-adapter-fastly = { git = "https://github.com/stackpop/edgezero", tag = "v0.0.8", default-features = false } -edgezero-adapter-spin = { git = "https://github.com/stackpop/edgezero", tag = "v0.0.8", default-features = false } -edgezero-cli = { git = "https://github.com/stackpop/edgezero", tag = "v0.0.8" } -edgezero-core = { git = "https://github.com/stackpop/edgezero", tag = "v0.0.8", default-features = false } +edgezero-adapter-axum = { git = "https://github.com/stackpop/edgezero", rev = "12c3215c2637d961a27eefa12e235033fadb4c4a", default-features = false } +edgezero-adapter-cloudflare = { git = "https://github.com/stackpop/edgezero", rev = "12c3215c2637d961a27eefa12e235033fadb4c4a", default-features = false } +edgezero-adapter-fastly = { git = "https://github.com/stackpop/edgezero", rev = "12c3215c2637d961a27eefa12e235033fadb4c4a", default-features = false } +edgezero-adapter-spin = { git = "https://github.com/stackpop/edgezero", rev = "12c3215c2637d961a27eefa12e235033fadb4c4a", default-features = false } +edgezero-cli = { git = "https://github.com/stackpop/edgezero", rev = "12c3215c2637d961a27eefa12e235033fadb4c4a" } +edgezero-core = { git = "https://github.com/stackpop/edgezero", rev = "12c3215c2637d961a27eefa12e235033fadb4c4a", 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..b173453eb 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; @@ -616,15 +617,7 @@ impl Hooks for TrustedServerApp { } fn routes() -> RouterService { - let state = match build_state() { - Ok(s) => s, - Err(ref e) => { - log::error!("failed to build application state: {:?}", e); - return startup_error_router(e); - } - }; - - build_router(&state) + Self::routes_with_server_timing_flag().0 } } @@ -669,6 +662,44 @@ impl TrustedServerApp { let state = build_state_with_services(settings, Some(services))?; 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: unlike the Fastly adapter, which rebuilds + /// `Settings` per request, the Axum dev server builds its application + /// state once and reuses the same [`RouterService`] for every request. + #[must_use] + fn routes_with_server_timing_flag() -> (RouterService, bool) { + let state = match build_state() { + Ok(s) => s, + Err(ref e) => { + log::error!("failed to build application state: {:?}", e); + return (startup_error_router(e), false); + } + }; + + let server_timing_enabled = state.settings.observability.server_timing_enabled; + (build_router(&state), server_timing_enabled) + } } fn build_router(state: &Arc) -> RouterService { diff --git a/crates/trusted-server-adapter-axum/src/lib.rs b/crates/trusted-server-adapter-axum/src/lib.rs index 2f15e566d..b1d4c3dd8 100644 --- a/crates/trusted-server-adapter-axum/src/lib.rs +++ b/crates/trusted-server-adapter-axum/src/lib.rs @@ -10,3 +10,6 @@ pub mod app; pub mod middleware; /// Platform-trait implementations backed by env vars and `reqwest`. pub mod platform; +/// Terminal timing layer wrapping the Axum dev server's tower `Service` +/// boundary with the request-phase `Server-Timing` freeze point. +pub mod timing; diff --git a/crates/trusted-server-adapter-axum/src/main.rs b/crates/trusted-server-adapter-axum/src/main.rs index 960982176..4e360ea41 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,63 @@ 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?; + + 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..315ebb5ef --- /dev/null +++ b/crates/trusted-server-adapter-axum/src/timing.rs @@ -0,0 +1,310 @@ +//! Terminal timing layer for the Axum dev server. +//! +//! [`TimingService`](crate::timing::TimingService) wraps the tower `Service` +//! boundary the Axum dev server's router sits behind: it creates a +//! [`RequestTimings`](trusted_server_core::request_timing::RequestTimings) +//! collector per request, threads it through request extensions so +//! downstream core handlers can record into it, and on the way back stamps +//! `mark_headers_ready` and appends the `Server-Timing` header via +//! [`append_server_timing_if_private`](trusted_server_core::request_timing::append_server_timing_if_private). +//! +//! This wraps *outside* `RouterService` rather than registering as +//! `RouterBuilder::middleware` 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: health checks never carry timing data on any +//! adapter. +//! +//! Unlike the Fastly adapter (state built per request, adding +//! `Phase::AppBuild` to the rendered header), the Axum dev server builds its +//! application state once at startup. There is no per-request app-build +//! interval to measure, so `ts-appbuild` never appears in the header here. + +use std::convert::Infallible; +use std::future::Future; +use std::pin::Pin; +use std::task::{Context, Poll}; + +use axum::body::Body as AxumBody; +use axum::http::{Request, Response}; +use tower::Service; +use trusted_server_core::request_timing::{RequestTimings, append_server_timing_if_private}; + +/// Path excluded from timing collection and `Server-Timing` emission: health +/// checks never carry timing data on any adapter. +const HEALTH_PATH: &str = "/health"; + +/// Wraps an inner Axum tower service with the request-phase timing freeze +/// point described in the module docs. +#[derive(Clone)] +pub struct TimingService { + inner: S, + server_timing_enabled: bool, +} + +impl TimingService { + /// Wraps `inner`, appending `Server-Timing` when `server_timing_enabled` + /// is set and the response is conclusively private. + #[must_use] + pub fn new(inner: S, server_timing_enabled: bool) -> Self { + Self { + inner, + server_timing_enabled, + } + } +} + +impl Service> for TimingService +where + S: Service, Response = Response, Error = Infallible> + + Clone + + Send + + 'static, + S::Future: Send + 'static, +{ + type Error = Infallible; + type Future = Pin> + Send>>; + type Response = Response; + + fn call(&mut self, mut req: Request) -> Self::Future { + let mut inner = self.inner.clone(); + + // Excluded before a collector is even created: `/health` never + // carries timing data, on any adapter. + if req.uri().path() == HEALTH_PATH { + return Box::pin(async move { inner.call(req).await }); + } + + let server_timing_enabled = self.server_timing_enabled; + let timings = RequestTimings::new(); + req.extensions_mut().insert(timings.clone()); + + Box::pin(async move { + let mut response = inner.call(req).await?; + append_server_timing_if_private(&mut response, &timings, server_timing_enabled); + Ok(response) + }) + } + + fn poll_ready(&mut self, cx: &mut Context<'_>) -> Poll> { + self.inner.poll_ready(cx) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use axum::http::header::CACHE_CONTROL; + use axum::http::{HeaderValue, StatusCode}; + use edgezero_adapter_axum::service::EdgeZeroAxumService; + use edgezero_core::body::Body as EdgeBody; + use edgezero_core::context::RequestContext; + use edgezero_core::error::EdgeError; + use edgezero_core::http::response_builder; + use edgezero_core::router::RouterService; + use tower::{ServiceExt as _, service_fn}; + + /// Builds a private (`cache-control: private, no-store`) response for a + /// handler under test. + fn private_ok_response() -> Result { + Ok(response_builder() + .status(StatusCode::OK) + .header("cache-control", "private, no-store") + .body(EdgeBody::from("ok")) + .expect("should build a private response fixture")) + } + + /// Reads a response header as a UTF-8 string, or `None` if absent. + fn header(response: &Response, name: &str) -> Option { + response + .headers() + .get(name) + .and_then(|value| value.to_str().ok()) + .map(ToOwned::to_owned) + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn axum_emits_header_on_private_response() { + let router = RouterService::builder() + .get("/private", |_ctx: RequestContext| async { + private_ok_response() + }) + .build(); + let mut service = TimingService::new(EdgeZeroAxumService::new(router), true); + + let request = Request::builder() + .uri("/private") + .body(AxumBody::empty()) + .expect("should build request"); + let response = service + .ready() + .await + .expect("should be ready") + .call(request) + .await + .expect("should not fail"); + + let server_timing = header(&response, "server-timing").expect("should emit header"); + assert!( + server_timing.contains("ts-total;dur="), + "should carry the collected total: {server_timing}" + ); + assert!( + !server_timing.contains("ts-appbuild"), + "the Axum dev server builds state once at startup, so there is no \ + per-request app-build interval to render: {server_timing}" + ); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn axum_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) = ctx.request().extensions().get::() { + 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() { + let router = RouterService::builder() + .get("/health", |_ctx: RequestContext| async { + private_ok_response() + }) + .build(); + let mut service = TimingService::new(EdgeZeroAxumService::new(router), true); + + let request = Request::builder() + .uri("/health") + .body(AxumBody::empty()) + .expect("should build request"); + let response = service + .ready() + .await + .expect("should be ready") + .call(request) + .await + .expect("should not fail"); + + assert!( + header(&response, "server-timing").is_none(), + "/health must never carry a server-timing header" + ); + } +} diff --git a/crates/trusted-server-adapter-cloudflare/src/app.rs b/crates/trusted-server-adapter-cloudflare/src/app.rs index 87b9567e7..fedcf7d96 100644 --- a/crates/trusted-server-adapter-cloudflare/src/app.rs +++ b/crates/trusted-server-adapter-cloudflare/src/app.rs @@ -42,7 +42,9 @@ use trusted_server_core::request_signing::{ }; use trusted_server_core::settings::Settings; -use crate::middleware::{AuthMiddleware, FinalizeResponseMiddleware, SanitizeRequestMiddleware}; +use crate::middleware::{ + AuthMiddleware, FinalizeResponseMiddleware, RequestTimingMiddleware, SanitizeRequestMiddleware, +}; use crate::platform::build_runtime_services; // --------------------------------------------------------------------------- @@ -602,6 +604,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::new()) .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..6b418688b 100644 --- a/crates/trusted-server-adapter-cloudflare/src/middleware.rs +++ b/crates/trusted-server-adapter-cloudflare/src/middleware.rs @@ -8,6 +8,7 @@ use edgezero_core::middleware::{Middleware, Next}; use trusted_server_core::auth::enforce_basic_auth; use trusted_server_core::constants::HEADER_X_GEO_INFO_AVAILABLE; use trusted_server_core::http_util::sanitize_trusted_client_ip_headers; +use trusted_server_core::request_timing::RequestTimings; use trusted_server_core::settings::Settings; // --------------------------------------------------------------------------- @@ -46,6 +47,40 @@ impl Middleware for SanitizeRequestMiddleware { } } +// --------------------------------------------------------------------------- +// RequestTimingMiddleware +// --------------------------------------------------------------------------- + +/// Attaches the server request clock consumed by core timing instrumentation. +/// +/// This adapter does not emit `Server-Timing`; the collector keeps timing +/// origins consistent for request-scoped consumers such as GPT diagnostics. +/// Health checks remain outside timing collection on every adapter. +#[derive(Default)] +pub struct RequestTimingMiddleware; + +impl RequestTimingMiddleware { + /// Creates a new [`RequestTimingMiddleware`]. + #[must_use] + pub fn new() -> Self { + Self + } +} + +#[async_trait(?Send)] +impl Middleware for RequestTimingMiddleware { + async fn handle(&self, mut ctx: RequestContext, next: Next<'_>) -> Result { + if ctx.request().uri().path() != "/health" + && ctx.request().extensions().get::().is_none() + { + ctx.request_mut() + .extensions_mut() + .insert(RequestTimings::new()); + } + next.run(ctx).await + } +} + // --------------------------------------------------------------------------- // FinalizeResponseMiddleware // --------------------------------------------------------------------------- @@ -56,9 +91,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`] and ahead of [`AuthMiddleware`] +/// so that every outgoing response — including auth-rejected ones — carries a +/// consistent set of headers. pub struct FinalizeResponseMiddleware { settings: Arc, } @@ -180,10 +215,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 +226,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 +328,34 @@ mod tests { ); } + #[test] + fn request_timing_middleware_attaches_a_collector_except_for_health() { + for (path, expected) in [("/test", true), ("/health", false)] { + let observed = Arc::new(Mutex::new(None)); + let handler_observed = Arc::clone(&observed); + let handler = Arc::new(move |ctx: RequestContext| { + let handler_observed = Arc::clone(&handler_observed); + async move { + *handler_observed.lock().expect("should lock observation") = + Some(ctx.request().extensions().get::().is_some()); + Ok::(empty_response()) + } + }); + + block_on( + RequestTimingMiddleware::new() + .handle(ctx_for_path(path), Next::new(&[], &*handler)), + ) + .expect("should run timing middleware"); + + assert_eq!( + *observed.lock().expect("should lock observation"), + Some(expected), + "collector presence should match timing policy for {path}" + ); + } + } + #[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 65320faa6..584085e76 100644 --- a/crates/trusted-server-adapter-fastly/Cargo.toml +++ b/crates/trusted-server-adapter-fastly/Cargo.toml @@ -28,6 +28,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 b19653c9e..e9a8b4e3f 100644 --- a/crates/trusted-server-adapter-fastly/src/app.rs +++ b/crates/trusted-server-adapter-fastly/src/app.rs @@ -90,16 +90,15 @@ use std::sync::Arc; use crate::rate_limiter::{FastlyRateLimiter, RATE_COUNTER_NAME}; use edgezero_adapter_fastly::context::FastlyRequestContext; -use edgezero_adapter_fastly::runtime_env_config; use edgezero_core::app::{App, Hooks, StoreMetadata, StoresMetadata}; use edgezero_core::context::RequestContext; -use edgezero_core::env_config::EnvConfig; use edgezero_core::error::EdgeError; use edgezero_core::http::{ HandlerFuture, HeaderValue, Method, Request, Response, StatusCode, header, }; 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 +118,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 +140,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}; @@ -162,11 +163,19 @@ pub(crate) struct RuntimeStoreConfig { } impl RuntimeStoreConfig { - pub(crate) fn from_env(env: &EnvConfig) -> Self { + /// Store bindings for the Fastly runtime. + /// + /// Store selection is a deploy-time input; no store selector reaches the + /// Fastly runtime. `EdgeZero` links each selected physical store to the + /// service version under its logical ID, so the runtime opens stores by + /// logical ID and reads the config entry under that same ID for every + /// publication target. Staging isolation comes from linking a different + /// physical store, never from a different key. + pub(crate) fn logical() -> Self { Self { - config_store_name: StoreName::from(env.store_name("config", DEFAULT_CONFIG_STORE_ID)), - config_key: env.store_key("config", DEFAULT_CONFIG_STORE_ID), - secret_store_name: StoreName::from(env.store_name("secrets", DEFAULT_SECRET_STORE_ID)), + config_store_name: StoreName::from(DEFAULT_CONFIG_STORE_ID), + config_key: DEFAULT_CONFIG_STORE_ID.to_owned(), + secret_store_name: StoreName::from(DEFAULT_SECRET_STORE_ID), } } } @@ -296,6 +305,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 // --------------------------------------------------------------------------- @@ -357,6 +372,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. @@ -412,13 +438,21 @@ fn build_ec_request_state( let eids_cookie = crate::extract_cookie_value(req, COOKIE_TS_EIDS); let sharedid_cookie = crate::extract_cookie_value(req, COOKIE_SHAREDID); - let geo_info = services - .geo() - .lookup(services.client_info().client_ip) - .unwrap_or_else(|e| { - log::warn!("geo lookup failed during EC setup: {e}"); - None - }); + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + let geo_info = { + let _span = timings.span(Phase::Geo); + services + .geo() + .lookup(services.client_info().client_ip) + .unwrap_or_else(|e| { + log::warn!("geo lookup failed during EC setup: {e}"); + None + }) + }; let (ec_context, setup_error) = match EcContext::read_from_request_with_geo(settings, req, services, geo_info.as_ref()) { @@ -439,7 +473,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())) { @@ -491,6 +525,18 @@ async fn run_pre_route_filters( req: &mut Request, geo_info: Option<&GeoInfo>, ) -> PreRoute { + // Only recorded when a filter is actually registered, so unconfigured + // deployments omit ts-filter from the Server-Timing header entirely. + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + let _span = state + .registry + .has_request_filters() + .then(|| timings.span(Phase::Filter)); + match state .registry .filter_request(RequestFilterRegistryInput { @@ -524,6 +570,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); @@ -574,7 +621,12 @@ async fn execute_named( // Deliberately do not use an EC request-state graph: that // copy is bot-gated, while operators use curl for this // authenticated diagnostic. - let kv = crate::maybe_identity_graph(&state.settings); + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + let kv = crate::identity_graph_with_timing(&state.settings, &timings); handle_admin_ec_lookup(kv.as_ref(), ®istry, &req) } NamedRouteHandler::AdminEidsLookup => handle_admin_eids_lookup(®istry, &req), @@ -648,7 +700,12 @@ async fn run_named_route( if req.method() == Method::OPTIONS { cors_preflight_identify(&state.settings, &req) } else { - let kv = crate::require_identity_graph(&state.settings)?; + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + let kv = crate::require_identity_graph_with_timing(&state.settings, &timings)?; let partner_registry = PartnerRegistry::from_config(&state.settings.ec.partners)?; handle_identify( &state.settings, @@ -731,12 +788,18 @@ fn run_batch_sync(state: &AppState, services: &RuntimeServices, req: Request) -> let is_real_browser = device_signals.looks_like_browser(); let eids_cookie = crate::extract_cookie_value(&req, COOKIE_TS_EIDS); let sharedid_cookie = crate::extract_cookie_value(&req, COOKIE_SHAREDID); + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); - let result = crate::require_identity_graph(&state.settings).and_then(|kv| { - let partner_registry = PartnerRegistry::from_config(&state.settings.ec.partners)?; - let limiter = FastlyRateLimiter::new(RATE_COUNTER_NAME); - handle_batch_sync(&kv, &partner_registry, &limiter, req) - }); + let result = + crate::require_identity_graph_with_timing(&state.settings, &timings).and_then(|kv| { + let partner_registry = PartnerRegistry::from_config(&state.settings.ec.partners)?; + let limiter = FastlyRateLimiter::new(RATE_COUNTER_NAME); + handle_batch_sync(&kv, &partner_registry, &limiter, req) + }); let mut response = result.unwrap_or_else(|e| http_error(&e)); // Legacy parity: batch-sync responses still pass through @@ -796,12 +859,35 @@ async fn dispatch_fallback( PreRoute::Continue { effects } => effects, }; + // Assigned exactly once, per branch below, alongside the routing + // decision itself, so the access-telemetry route identity always + // reflects which branch actually dispatched the request — including + // when that branch's handler errors. The asset-route sub-branch is an + // early return handled separately by `dispatch_asset_fallback`, so it + // never reaches (or needs to assign) this binding. + let route_metadata: Option; + let result = if uses_dynamic_tsjs_fallback(&method, &path) { + route_metadata = Some(RouteMetadata { + route_class: RouteClass::Tsjs, + route_template: TSJS_ROUTE_TEMPLATE.to_owned(), + }); handle_tsjs_dynamic(&req, &state.registry, EdgeCacheHeader::SurrogateControl) } else if state.registry.has_route(&method, &path) { // Integration-proxy responses are not bounded by // publisher.max_buffered_body_bytes. Publisher fallback below uses the // publisher-specific streaming finalizer instead. + // 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: state + .registry + .matched_route_pattern(&method, &path) + .map_or_else(|| "/other/*".to_owned(), str::to_owned), + }); state .registry .handle_proxy(ProxyDispatchInput { @@ -829,9 +915,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. @@ -897,7 +1008,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) } @@ -921,7 +1035,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` @@ -936,6 +1053,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"); @@ -957,6 +1075,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 } @@ -965,6 +1084,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 } @@ -1088,6 +1208,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 @@ -1110,21 +1234,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` @@ -1134,6 +1262,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. @@ -1141,11 +1270,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. @@ -1153,6 +1284,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 @@ -1164,36 +1296,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. @@ -1201,6 +1340,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 @@ -1211,21 +1351,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", @@ -1234,16 +1382,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 + }) + }) } } @@ -1304,7 +1471,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, + ), ); } @@ -1332,8 +1504,7 @@ impl Hooks for TrustedServerApp { } fn routes() -> RouterService { - let runtime_env = runtime_env_config(Self::stores()); - let stores = RuntimeStoreConfig::from_env(&runtime_env); + let stores = RuntimeStoreConfig::logical(); Self::router_with_state(&stores).0 } @@ -1364,19 +1535,20 @@ 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; use edgezero_core::app::Hooks as _; use edgezero_core::body::Body; use edgezero_core::context::RequestContext; - 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; @@ -1385,20 +1557,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] @@ -1445,32 +1620,8 @@ mod tests { } #[test] - fn runtime_store_config_maps_logical_store_names_and_config_key() { - let env = EnvConfig::from_vars([ - ( - "EDGEZERO__STORES__CONFIG__TRUSTED_SERVER_CONFIG__NAME", - "physical_config", - ), - ( - "EDGEZERO__STORES__CONFIG__TRUSTED_SERVER_CONFIG__KEY", - "active_config", - ), - ( - "EDGEZERO__STORES__SECRETS__TRUSTED_SERVER_SECRETS__NAME", - "ts_secrets", - ), - ]); - - let stores = RuntimeStoreConfig::from_env(&env); - - assert_eq!(stores.config_store_name.as_ref(), "physical_config"); - assert_eq!(stores.config_key, "active_config"); - assert_eq!(stores.secret_store_name.as_ref(), "ts_secrets"); - } - - #[test] - fn runtime_store_config_uses_logical_defaults_without_overrides() { - let stores = RuntimeStoreConfig::from_env(&EnvConfig::default()); + fn runtime_store_config_opens_logical_store_ids_and_key() { + let stores = RuntimeStoreConfig::logical(); assert_eq!(stores.config_store_name.as_ref(), "trusted_server_config"); assert_eq!(stores.config_key, "trusted_server_config"); @@ -1577,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) @@ -1594,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, ), @@ -1602,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 @@ -2225,8 +2383,9 @@ mod tests { .to_str() .expect("should render set-cookie as utf-8"); assert_eq!( - set_cookie, "ts-tester=true; Domain=.test-publisher.com; Path=/; Secure; SameSite=Lax", - "tester cookie should use publisher.cookie_domain" + set_cookie, + "ts-tester=true; Domain=.test-publisher.com; Path=/; Secure; SameSite=Lax; Max-Age=2592000", + "tester cookie should use publisher.cookie_domain and persist across browser restarts" ); } @@ -2378,6 +2537,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" + ); + } + #[test] fn browser_device_signals_from_extension_reach_ec_finalize_state() { // Regression guard for the EdgeZero JA4/H2 signal loss: `edgezero_main` @@ -2729,6 +2996,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 { @@ -3151,6 +3473,7 @@ mod tests { req, asset_route, &effects, + trusted_server_core::geo::GeoLookupState::NotAttempted, )); assert_eq!( @@ -3194,6 +3517,251 @@ mod tests { ); } + /// A [`PlatformGeo`] stub that counts every `lookup` call and always + /// returns the same canned result, used to prove the request-phase geo + /// lookup is never repeated during finalize. + struct CountingGeo { + calls: Arc, + result: Option, + } + + impl PlatformGeo for CountingGeo { + fn lookup(&self, _: Option) -> Result, Report> { + self.calls.fetch_add(1, Ordering::SeqCst); + Ok(self.result.clone()) + } + } + + fn sample_geo_info() -> GeoInfo { + GeoInfo { + city: "Testville".to_string(), + country: "US".to_string(), + continent: "NorthAmerica".to_string(), + latitude: 0.0, + longitude: 0.0, + metro_code: 0, + region: None, + asn: None, + } + } + + fn runtime_services_with_geo(geo: Arc) -> RuntimeServices { + RuntimeServices::builder() + .config_store(Arc::new(crate::platform::FastlyPlatformConfigStore)) + .secret_store(Arc::new(crate::platform::FastlyPlatformSecretStore)) + .kv_store(Arc::new(NoopKvStore) as Arc) + .backend(Arc::new(FixedBackend)) + .http_client(Arc::new(StreamingHttpClient)) + .geo(geo) + .client_info(ClientInfo::default()) + .build() + } + + #[test] + fn finalize_reuses_request_phase_geo_without_second_lookup() { + // Dispatching a publisher route runs build_ec_request_state, which + // attempts the geo lookup once and carries the result via + // GeoLookupState. The finalize step (resolve_geo_for_response) must + // reuse that carried value instead of calling the geo backend again. + let calls = Arc::new(AtomicUsize::new(0)); + let geo = Arc::new(CountingGeo { + calls: Arc::clone(&calls), + result: Some(sample_geo_info()), + }); + let state = app_state_for_settings(test_settings()); + let services = runtime_services_with_geo(geo); + let req = empty_request(Method::GET, "/some-page"); + + let response = block_on(super::dispatch_fallback(&state, &services, req)); + + let carried = response + .extensions() + .get::() + .cloned() + .expect("dispatch should attach GeoLookupState"); + assert!( + matches!(carried, GeoLookupState::Resolved(_)), + "a successful lookup should carry Resolved" + ); + + let geo_info = + crate::middleware::resolve_geo_for_response(&response, &carried, None, |_| { + panic!("finalize must not repeat a resolved geo lookup"); + }); + + assert_eq!( + calls.load(Ordering::SeqCst), + 1, + "only the request-phase lookup should have run" + ); + + let mut response = response; + geo_info + .expect("geo info should have resolved") + .set_response_headers(&mut response); + assert!( + response.headers().get(HEADER_X_GEO_COUNTRY).is_some(), + "x-geo-country should still be set on the response after reusing the carried geo" + ); + } + + #[test] + fn failed_lookup_is_not_retried() { + // When the request-phase lookup fails (returns None), dispatch must + // carry GeoLookupState::Attempted rather than NotAttempted, and + // finalize must not retry it. + let calls = Arc::new(AtomicUsize::new(0)); + let geo = Arc::new(CountingGeo { + calls: Arc::clone(&calls), + result: None, + }); + let state = app_state_for_settings(test_settings()); + let services = runtime_services_with_geo(geo); + let req = empty_request(Method::GET, "/some-page"); + + let response = block_on(super::dispatch_fallback(&state, &services, req)); + + let carried = response + .extensions() + .get::() + .cloned() + .expect("dispatch should attach GeoLookupState even for a failed lookup"); + assert!( + matches!(carried, GeoLookupState::Attempted), + "a failed lookup should carry Attempted, not Resolved or NotAttempted" + ); + + let geo_info = + crate::middleware::resolve_geo_for_response(&response, &carried, None, |_| { + panic!("finalize must not retry a failed geo lookup"); + }); + + assert_eq!( + calls.load(Ordering::SeqCst), + 1, + "only the request-phase lookup should have run" + ); + assert!( + geo_info.is_none(), + "no geo info should be available after a failed lookup" + ); + } + + #[test] + fn filter_span_recorded_when_request_filter_runs() { + // The Filter phase span should only be recorded when the registry + // actually has a request filter registered, so unconfigured + // deployments omit ts-filter from the Server-Timing header entirely. + let state = state_with_request_filters(vec![Arc::new(RecordingRequestFilter)]); + let services = RuntimeServices::builder() + .config_store(Arc::new(crate::platform::FastlyPlatformConfigStore)) + .secret_store(Arc::new(crate::platform::FastlyPlatformSecretStore)) + .kv_store(Arc::new(NoopKvStore) as Arc) + .backend(Arc::new(FixedBackend)) + .http_client(Arc::new(StreamingHttpClient)) + .geo(Arc::new(crate::platform::FastlyPlatformGeo)) + .client_info(ClientInfo::default()) + .build(); + let mut req = empty_request(Method::GET, "/some-page"); + let timings = RequestTimings::new(); + req.extensions_mut().insert(timings.clone()); + + let _ = block_on(super::run_pre_route_filters( + &state, &services, &mut req, None, + )); + + assert!( + timings.snapshot().filter_ms.is_some(), + "should record the Filter phase span when a request filter is registered and runs" + ); + } + + #[test] + fn filter_span_not_recorded_when_no_request_filters_registered() { + // Mirror test: an empty registry must never record the Filter span, + // even though run_pre_route_filters still runs (as a no-op loop). + let state = state_with_request_filters(Vec::new()); + let services = RuntimeServices::builder() + .config_store(Arc::new(crate::platform::FastlyPlatformConfigStore)) + .secret_store(Arc::new(crate::platform::FastlyPlatformSecretStore)) + .kv_store(Arc::new(NoopKvStore) as Arc) + .backend(Arc::new(FixedBackend)) + .http_client(Arc::new(StreamingHttpClient)) + .geo(Arc::new(crate::platform::FastlyPlatformGeo)) + .client_info(ClientInfo::default()) + .build(); + let mut req = empty_request(Method::GET, "/some-page"); + let timings = RequestTimings::new(); + req.extensions_mut().insert(timings.clone()); + + let _ = block_on(super::run_pre_route_filters( + &state, &services, &mut req, None, + )); + + assert!( + timings.snapshot().filter_ms.is_none(), + "should omit the Filter phase span when no request filters are registered" + ); + } + + fn settings_with_consent_and_ec_store() -> Settings { + Settings::from_toml( + r#" + [[handlers]] + path = "^/_ts/admin" + username = "admin" + password = "admin-pass" + + [publisher] + domain = "test-publisher.com" + cookie_domain = ".test-publisher.com" + origin_url = "https://origin.test-publisher.com" + proxy_secret = "unit-test-proxy-secret" + + [ec] + passphrase = "test-secret-key-32-bytes-minimum" + ec_store = "ec_identity_store" + + [request_signing] + enabled = false + config_store_id = "test-config-store-id" + secret_store_id = "test-secret-store-id" + "#, + ) + .expect("should parse settings with consent and EC KV stores configured") + } + + #[test] + fn identity_store_reads_are_timed_and_pull_sync_is_not() { + let settings = settings_with_consent_and_ec_store(); + let timings = RequestTimings::new(); + + let graph = crate::identity_graph_with_timing(&settings, &timings) + .expect("should construct the configured identity graph"); + let _ = graph.get("timed-identity-read-key"); + + timings.mark_headers_ready(); + assert!( + timings.snapshot().kv_ms.is_some(), + "an identity-store read should record Phase::EcKv" + ); + + // Pull-sync's identity graph is built by `require_identity_graph`, + // which takes no `timings` parameter at all — the untimed store it + // constructs cannot record into any handle, including a fresh one. + let graph = crate::require_identity_graph(&settings) + .expect("should construct the pull-sync identity graph"); + let ec_id = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.test01"; + let _ = graph.get(ec_id); + + let pull_sync_timings = RequestTimings::new(); + pull_sync_timings.mark_headers_ready(); + assert!( + pull_sync_timings.snapshot().kv_ms.is_none(), + "pull-sync's untimed graph construction has no timings handle to record into" + ); + } + #[test] fn dispatch_runs_request_filter_and_threads_response_effects() { // Regression guard for the EdgeZero request-filter bypass: the publisher @@ -3253,6 +3821,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() @@ -3296,6 +3919,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 @@ -3333,6 +3982,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 ce7264e78..099e40211 100644 --- a/crates/trusted-server-adapter-fastly/src/main.rs +++ b/crates/trusted-server-adapter-fastly/src/main.rs @@ -1,9 +1,10 @@ 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; -use edgezero_core::app::Hooks as _; use edgezero_core::body::Body as EdgeBody; use edgezero_core::config_store::ConfigStoreHandle; use edgezero_core::error::EdgeError; @@ -13,7 +14,13 @@ use error_stack::Report; use fastly::http::Method as FastlyMethod; use fastly::{Request as FastlyRequest, Response as FastlyResponse}; +use trusted_server_core::access_telemetry::{ + AccessTelemetrySnapshot, RouteClass, RouteMetadata, access_event_row, +}; use trusted_server_core::cache_policy::EdgeCacheHeader; +use trusted_server_core::constants::{ + ENV_FASTLY_IS_STAGING, ENV_FASTLY_POP, ENV_FASTLY_SERVICE_ID, ENV_FASTLY_SERVICE_VERSION, +}; use trusted_server_core::ec::device::DeviceSignals; use trusted_server_core::ec::finalize::ec_finalize_response; use trusted_server_core::ec::kv::KvIdentityGraph; @@ -22,9 +29,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; @@ -89,8 +100,7 @@ fn main() { /// Handles a request through the `EdgeZero` router path. fn edgezero_main(mut req: FastlyRequest) { - let runtime_env = runtime_env_config(TrustedServerApp::stores()); - let runtime_stores = RuntimeStoreConfig::from_env(&runtime_env); + let runtime_stores = RuntimeStoreConfig::logical(); // Short-circuit the JA4 debug probe before app construction. Must run here // because TLS/JA4 accessors are only available on FastlyRequest before @@ -113,20 +123,43 @@ fn edgezero_main(mut req: FastlyRequest) { return; } - let config_store = - match open_trusted_server_config_store(runtime_stores.config_store_name.as_ref()) { - Ok(cs) => cs, - Err(e) => { - log::error!("failed to open config store: {e}"); - FastlyResponse::from_status(fastly::http::StatusCode::INTERNAL_SERVER_ERROR) - .with_body_text_plain("Internal Server Error") - .send_to_client(); - return; - } - }; + let timings = RequestTimings::new(); - let (app, app_state) = TrustedServerApp::build_app_with_state(&runtime_stores); + let (config_store, app, app_state) = { + let _appbuild = timings.span(Phase::AppBuild); + let config_store = + match open_trusted_server_config_store(runtime_stores.config_store_name.as_ref()) { + Ok(cs) => cs, + Err(e) => { + log::error!("failed to open config store: {e}"); + FastlyResponse::from_status(fastly::http::StatusCode::INTERNAL_SERVER_ERROR) + .with_body_text_plain("Internal Server Error") + .send_to_client(); + return; + } + }; + let (app, app_state) = TrustedServerApp::build_app_with_state(&runtime_stores); + (config_store, app, app_state) + }; let settings_snapshot = app_state.as_ref().map(|state| Arc::clone(&state.settings)); + let server_timing_enabled = settings_snapshot + .as_deref() + .is_some_and(|settings| settings.observability.server_timing_enabled); + // Both read once here rather than at each `send_edgezero_response` call + // site: if `app_state` failed to build, there is no settings snapshot to + // read them from at all, so every call site would need the same + // degraded-mode fallback. `access_sample_rate` defaults to `0.0` (never + // sampled in) and `publisher_domain` to `"unknown"` in that case. + let access_sample_rate = settings_snapshot + .as_deref() + .map_or(0.0, |settings| settings.tinybird.access_sample_rate); + let access_telemetry_enabled = settings_snapshot + .as_deref() + .is_some_and(|settings| settings.tinybird.enabled && settings.tinybird.access_enabled); + let publisher_domain = settings_snapshot.as_deref().map_or_else( + || "unknown".to_owned(), + |settings| settings.publisher.domain.clone(), + ); let trusted_client_ip = settings_snapshot .as_deref() .and_then(|settings| settings.trusted_client_ip.as_ref()); @@ -146,6 +179,10 @@ fn edgezero_main(mut req: FastlyRequest) { 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_str().to_owned(); + // Strip any client-supplied x-ts-tls-* headers before injecting the trusted // values from the Fastly SDK. Must run after sanitize_fastly_forwarded_headers. req.remove_header("x-ts-tls-protocol"); @@ -177,6 +214,7 @@ fn edgezero_main(mut req: FastlyRequest) { core_req.extensions_mut().insert(config_store); core_req.extensions_mut().insert(device_signals); core_req.extensions_mut().insert(client_info); + core_req.extensions_mut().insert(timings.clone()); match futures::executor::block_on(app.router().oneshot(core_req)) { Ok(response) => response, Err(error) => edge_error_response(error), @@ -195,14 +233,34 @@ fn edgezero_main(mut req: FastlyRequest) { let ec_state = response.extensions_mut().remove::(); let asset_cache_policy = response.extensions_mut().remove::(); let request_filter_effects = response.extensions_mut().remove::(); + // Read rather than pop: the access-telemetry snapshot built later in + // `send_edgezero_response` reads this same extension, so it must still + // be attached to `response` at that point. + let geo_lookup_state = response + .extensions() + .get::() + .cloned() + .unwrap_or(GeoLookupState::NotAttempted); if !take_finalize_sentinel(&mut response) { if let Some(settings) = settings_snapshot.as_deref() { - apply_entry_point_finalize_headers(settings, &mut response, client_ip); + apply_entry_point_finalize_headers( + settings, + &mut response, + client_ip, + &geo_lookup_state, + &timings, + ); } else { match load_settings_from_config_store(&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:?}"); @@ -217,10 +275,30 @@ fn edgezero_main(mut req: FastlyRequest) { 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(response, request_filter_effects.as_ref()); - run_edgezero_pull_sync_after_send(settings, &partner_registry, &ec_state); + let outcome = send_edgezero_response( + response, + request_filter_effects.as_ref(), + &SendContext { + timings: timings.clone(), + server_timing_enabled, + method: request_method.clone(), + publisher_domain: publisher_domain.clone(), + access_sample_rate, + access_telemetry_enabled, + }, + ); + run_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) => { @@ -232,13 +310,34 @@ fn edgezero_main(mut req: FastlyRequest) { } 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(response, request_filter_effects.as_ref()); - run_edgezero_pull_sync_after_send( - &settings, - &partner_registry, - &ec_state, + let outcome = send_edgezero_response( + response, + request_filter_effects.as_ref(), + &SendContext { + timings: timings.clone(), + server_timing_enabled, + method: request_method.clone(), + publisher_domain: publisher_domain.clone(), + access_sample_rate, + access_telemetry_enabled, + }, + ); + run_post_send_steps( + || { + run_edgezero_pull_sync_after_send( + &settings, + &partner_registry, + &ec_state, + ); + }, + || emit_access_telemetry_after_send(&settings, &outcome, &timings), ); return; } @@ -256,7 +355,27 @@ fn edgezero_main(mut req: FastlyRequest) { } } - send_edgezero_response(response, request_filter_effects.as_ref()); + let outcome = send_edgezero_response( + response, + request_filter_effects.as_ref(), + &SendContext { + timings: timings.clone(), + server_timing_enabled, + method: request_method, + publisher_domain, + access_sample_rate, + access_telemetry_enabled, + }, + ); + // The asset/admin/error fallback path: no `EcFinalizeState` (or the ec + // finalize branch above failed), so there is no pull-sync dispatch here + // at all — telemetry is the only post-send step. 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 { @@ -284,24 +403,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 }; @@ -362,6 +493,232 @@ 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. +/// +/// Sampled-out requests return silently — that is the expected, high-volume +/// case and not worth a log line. The sampling roll uses the rate stored on +/// the snapshot itself, so the emission probability always matches the +/// row's `sample_rate` column by construction. Every other drop (row +/// build, token load, send, or non-2xx status — all folded into +/// `emit_access_event`'s `Result`) logs exactly one warning naming the +/// reason. +fn emit_access_telemetry_after_send( + settings: &Settings, + outcome: &DeliveryOutcome, + timings: &RequestTimings, +) { + if !settings.tinybird.enabled || !settings.tinybird.access_enabled { + return; + } + + // No snapshot means access telemetry was disabled when the response + // was sent (the flag is read once, before dispatch); nothing to emit. + let Some(snapshot) = &outcome.snapshot else { + return; + }; + + let since_epoch = SystemTime::now() + .duration_since(UNIX_EPOCH) + .unwrap_or_default(); + let epoch_ms = u64::try_from(since_epoch.as_millis()).unwrap_or(u64::MAX); + // Sample with the rate stored on the snapshot itself — the same value + // serialized into the row's `sample_rate` column — so the emission + // probability and the row's claimed rate cannot diverge, which the + // documented `sum(1.0 / sample_rate)` volume estimator depends on. + let roll = rand::thread_rng().r#gen::(); + if !tinybird::sampled_in(snapshot.sample_rate, roll) { + return; + } + + let row = access_event_row(snapshot, &timings.snapshot(), epoch_ms); + let target = tinybird::TinybirdEventsTarget::from_access_config(settings.tinybird.clone()); + let result = futures::executor::block_on(tinybird::emit_access_event( + &platform::FastlyPlatformHttpClient, + &target, + row, + )); + if let Err(error) = result { + log::warn!("access telemetry emission dropped: {error:?}"); + } +} + +/// Per-response context threaded into [`send_edgezero_response`] so the +/// function stays at or under seven parameters. +struct SendContext { + /// The request's phase-timing collector. + timings: RequestTimings, + /// Whether `observability.server_timing_enabled` is set. + server_timing_enabled: bool, + /// The request's HTTP method, captured before the request was consumed + /// by dispatch. + method: String, + /// The configured publisher domain. + publisher_domain: String, + /// The configured access-telemetry sample rate. + access_sample_rate: f64, + /// Whether `tinybird.enabled` and `tinybird.access_enabled` were both + /// set when settings were first read. Gates building the + /// [`AccessTelemetrySnapshot`] at all: the snapshot costs env reads and + /// `String` allocations on the pre-send path, which a disabled + /// deployment (the default) should not pay. + access_telemetry_enabled: bool, +} + +/// Outcome of handing a finalized response to the client. +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 at snapshot + /// time; the emitter treats that as nothing to send. + pub snapshot: Option, +} + +/// Whether [`send_edgezero_response`] completed delivery or failed partway. +#[derive(Debug, PartialEq, Eq)] +pub(crate) enum DeliveryResult { + /// The response was handed to the client in full. + Complete, + /// Delivery started but did not finish cleanly: some bytes reached the + /// client's transport before a stream error, or the transport could not + /// be closed cleanly after every byte was written. + Partial, + /// Delivery failed before any bytes reached the client. + Error, +} + +/// Thin Fastly-adapter wrapper around +/// [`append_server_timing_if_private`], the freeze point shared with the +/// Axum adapter's terminal timing layer. See that function's doc for the +/// emission rules (always stamps `mark_headers_ready`; appends rather than +/// overwrites; never promotes a response to shared-cacheable). +pub(crate) fn apply_server_timing_header( + response: &mut HttpResponse, + timings: &RequestTimings, + server_timing_enabled: bool, +) { + append_server_timing_if_private(response, timings, server_timing_enabled); +} + +/// A [`Write`](std::io::Write) wrapper that tallies bytes successfully written +/// to the inner writer. +/// +/// Wraps the client transport during a streaming drive so a truncated or +/// failed drive still reports how many bytes actually reached it, instead of +/// the placeholder `0` a failed/aborted drive would otherwise report. +struct CountingWriter { + inner: W, + bytes: u64, +} + +impl CountingWriter { + fn new(inner: W) -> Self { + Self { inner, bytes: 0 } + } + + /// Bytes successfully written to the inner writer so far. + fn bytes(&self) -> u64 { + self.bytes + } + + fn into_inner(self) -> W { + self.inner + } +} + +impl std::io::Write for CountingWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let written = self.inner.write(buf)?; + self.bytes = self.bytes.saturating_add(written as u64); + Ok(written) + } + + fn flush(&mut self) -> std::io::Result<()> { + self.inner.flush() + } +} + +/// Drives a streaming `EdgeZero` body through `output`, tallying bytes written +/// and timing the drive into `timings`. +/// +/// Stamps `resp_bytes` and `request_elapsed` immediately once the drive +/// returns — before the caller does anything transport-specific (finishing +/// the streaming body, logging) — so `request_elapsed` never includes that +/// work. Returns the counting writer (so the caller can recover both the +/// tallied byte count and the wrapped transport) alongside the drive's +/// result. +fn drive_streaming_body( + body: EdgeBody, + output: W, + timings: &RequestTimings, +) -> (CountingWriter, Result<(), Report>) { + let mut counting = CountingWriter::new(output); + let drive_started = Instant::now(); + let result = futures::executor::block_on(stream_asset_body(body, &mut counting)); + timings.record(Phase::Stream, drive_started.elapsed()); + timings.set_resp_bytes(counting.bytes()); + timings.mark_request_elapsed(); + (counting, result) +} + +/// Classifies a completed streaming drive into a [`DeliveryResult`]. +/// +/// A drive that failed after writing at least one byte delivered a truncated +/// response rather than nothing at all, so it is [`DeliveryResult::Partial`], +/// not [`DeliveryResult::Error`]. +/// +/// 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 @@ -370,8 +727,24 @@ where fn send_edgezero_response( mut response: HttpResponse, request_filter_effects: Option<&RequestFilterEffects>, -) { + context: &SendContext, +) -> DeliveryOutcome { apply_terminal_response_effects(&mut response, request_filter_effects); + apply_server_timing_header( + &mut response, + &context.timings, + context.server_timing_enabled, + ); + + // Built right after the freeze point and before `into_parts()` + // consumes `response`: nothing else survives to post-send on every + // path (the request was consumed by dispatch, and `EcFinalizeState` + // is absent on asset, admin, and error paths). Skipped entirely when + // access telemetry is disabled, so the default configuration pays no + // env reads or allocations here. + let snapshot = context + .access_telemetry_enabled + .then(|| build_access_telemetry_snapshot(&response, context)); let (parts, body) = response.into_parts(); @@ -381,25 +754,133 @@ fn send_edgezero_response( parts, EdgeBody::empty(), )); - let mut streaming_body = skeleton.stream_to_client(); - match futures::executor::block_on(stream_asset_body(body, &mut streaming_body)) { - Ok(()) => { - if let Err(e) = streaming_body.finish() { + let (counting, drive_result) = + drive_streaming_body(body, skeleton.stream_to_client(), &context.timings); + let bytes = counting.bytes(); + let streaming_body = counting.into_inner(); + // Computed before `drive_result` is matched by value below, since + // the `Err` arm there moves its `Report` out. + let result = classify_stream_delivery(&drive_result, bytes); + match drive_result { + Ok(()) => match streaming_body.finish() { + Ok(()) => DeliveryOutcome { + bytes, + result: DeliveryResult::Complete, + snapshot, + }, + Err(e) => { + // Every byte was handed to the transport (the drive + // above returned Ok), but the transport itself could + // not close cleanly — the client may still see a + // truncated response. log::error!("failed to finish EdgeZero streaming body: {e}"); + DeliveryOutcome { + bytes, + result: DeliveryResult::Partial, + snapshot, + } } - } + }, Err(e) => { log::error!("EdgeZero streaming failed: {e:?}"); drop(streaming_body); + DeliveryOutcome { + bytes, + result, + snapshot, + } } } } once => { + let bytes = record_buffered_delivery(&once, &context.timings); compat::to_fastly_response(HttpResponse::from_parts(parts, once)).send_to_client(); + DeliveryOutcome { + bytes, + result: DeliveryResult::Complete, + snapshot, + } } } } +/// Builds the [`AccessTelemetrySnapshot`] for `response` at the +/// `Server-Timing` freeze point. +/// +/// Reads route identity, geo country, and template-cache state from typed +/// response extensions rather than the headers those extensions back — +/// operator-configured response headers can override a managed header, so +/// reading a header here could silently drift from what actually happened. +/// Falls back to `"unknown"`/[`RouteClass::Other`] sentinels when an +/// extension was never attached (router-generated, asset, and other +/// responses that never passed through a `RouteMetadata`-attaching +/// wrapper). +fn build_access_telemetry_snapshot( + response: &HttpResponse, + context: &SendContext, +) -> AccessTelemetrySnapshot { + let (route_class, route_template) = match response.extensions().get::() { + Some(metadata) => (metadata.route_class, metadata.route_template.clone()), + None => (RouteClass::Other, "unknown".to_owned()), + }; + + let country = match response.extensions().get::() { + Some(GeoLookupState::Resolved(info)) => info.country.clone(), + Some(GeoLookupState::Attempted | GeoLookupState::NotAttempted) | None => { + "unknown".to_owned() + } + }; + + let template_cache_state = response + .extensions() + .get::() + .map_or_else(|| "unknown".to_owned(), |state| state.as_str().to_owned()); + + let body_mode = if matches!(response.body(), EdgeBody::Stream(_)) { + "streamed" + } else { + "buffered" + }; + + AccessTelemetrySnapshot { + method: context.method.clone(), + status: response.status().as_u16(), + route_class, + route_template, + publisher_domain: context.publisher_domain.clone(), + env: resolve_env_dimension(), + service_id: env_var_or_unknown(ENV_FASTLY_SERVICE_ID), + pop: env_var_or_unknown(ENV_FASTLY_POP), + ts_version: env_var_or_unknown(ENV_FASTLY_SERVICE_VERSION), + country, + template_cache_state, + body_mode, + sample_rate: context.access_sample_rate, + } +} + +/// Derives the `env` access-telemetry dimension from the same +/// `FASTLY_IS_STAGING` input that drives the `x-ts-env` response header +/// (see [`apply_finalize_headers`]), never from [`Settings`] — `Settings` +/// has no environment field and does not gain one for this. +/// +/// `"unknown"` covers contexts where the variable is entirely absent (for +/// example native unit tests run outside Fastly Compute); on the Fastly +/// platform the variable is always present, as either `"1"` or not. +fn resolve_env_dimension() -> String { + match std::env::var(ENV_FASTLY_IS_STAGING) { + Ok(value) if value == "1" => "staging".to_owned(), + Ok(_) => "production".to_owned(), + Err(_) => "unknown".to_owned(), + } +} + +/// Reads a Fastly-provided environment variable, defaulting to `"unknown"` +/// when unset. +fn env_var_or_unknown(name: &str) -> String { + std::env::var(name).unwrap_or_else(|_| "unknown".to_owned()) +} + /// Apply every late response mutation, then restore privacy invariants before headers commit. fn apply_terminal_response_effects( response: &mut HttpResponse, @@ -471,16 +952,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> { @@ -493,6 +989,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())?; @@ -521,12 +1038,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( @@ -554,6 +1077,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); @@ -806,9 +1349,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!( @@ -874,4 +1418,432 @@ 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" + ); + + 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 { + SendContext { + timings: RequestTimings::new(), + server_timing_enabled: false, + method: "GET".to_owned(), + publisher_domain: "test-publisher.com".to_owned(), + access_sample_rate: 0.25, + access_telemetry_enabled: true, + } + } + + #[test] + fn access_snapshot_defaults_when_no_extensions_are_attached() { + // Router-generated 404/405 responses and other paths that never pass + // through a RouteMetadata-attaching wrapper must still produce a + // usable snapshot: RouteClass::Other and "unknown" sentinels, never + // a missing/panicking build. + let response = response_builder() + .status(404) + .body(EdgeBody::empty()) + .expect("should build response"); + let context = send_context_fixture(); + + let snapshot = build_access_telemetry_snapshot(&response, &context); + + assert_eq!(snapshot.status, 404); + assert_eq!(snapshot.method, "GET"); + assert!(matches!(snapshot.route_class, RouteClass::Other)); + assert_eq!(snapshot.route_template, "unknown"); + assert_eq!(snapshot.country, "unknown"); + assert_eq!(snapshot.template_cache_state, "unknown"); + assert_eq!(snapshot.body_mode, "buffered"); + assert_eq!(snapshot.publisher_domain, "test-publisher.com"); + assert_eq!(snapshot.sample_rate, 0.25); + } + + #[test] + fn access_snapshot_reads_route_geo_and_template_cache_extensions() { + let mut response = response_builder() + .status(200) + .body(EdgeBody::empty()) + .expect("should build response"); + response.extensions_mut().insert(RouteMetadata { + route_class: RouteClass::AuctionApi, + route_template: "/auction".to_owned(), + }); + response.extensions_mut().insert(GeoLookupState::Resolved( + trusted_server_core::platform::GeoInfo { + city: String::new(), + country: "US".to_owned(), + continent: "NorthAmerica".to_owned(), + latitude: 0.0, + longitude: 0.0, + metro_code: 0, + region: None, + asn: None, + }, + )); + response + .extensions_mut() + .insert(TemplateCacheResponseState::Hit); + let context = send_context_fixture(); + + let snapshot = build_access_telemetry_snapshot(&response, &context); + + assert!(matches!(snapshot.route_class, RouteClass::AuctionApi)); + assert_eq!(snapshot.route_template, "/auction"); + assert_eq!(snapshot.country, "US"); + assert_eq!(snapshot.template_cache_state, "hit"); + } + + #[test] + fn access_snapshot_treats_attempted_geo_lookup_as_unknown_country() { + let mut response = response_builder() + .status(200) + .body(EdgeBody::empty()) + .expect("should build response"); + response.extensions_mut().insert(GeoLookupState::Attempted); + let context = send_context_fixture(); + + let snapshot = build_access_telemetry_snapshot(&response, &context); + + assert_eq!( + snapshot.country, "unknown", + "an attempted-but-unresolved lookup must not surface a stale country" + ); + } + + #[test] + fn access_snapshot_body_mode_reflects_the_response_body_variant() { + let streamed = response_builder() + .status(200) + .body(EdgeBody::stream(futures::stream::empty())) + .expect("should build streaming response"); + let buffered = response_builder() + .status(200) + .body(EdgeBody::from(b"hi".to_vec())) + .expect("should build buffered response"); + let context = send_context_fixture(); + + assert_eq!( + build_access_telemetry_snapshot(&streamed, &context).body_mode, + "streamed" + ); + assert_eq!( + build_access_telemetry_snapshot(&buffered, &context).body_mode, + "buffered" + ); + } + + #[test] + fn stream_drive_records_stream_ms_covering_the_in_stream_auction_wait() { + // A streaming seam wait (Task 6, publisher.rs) records into the same + // `RequestTimings` handle the adapter drives with. `Phase::Stream` + // wraps the entire drive, so it must cover — and therefore be at + // least as large as — any `AuctionWait` recorded while the body was + // being polled. + let timings = RequestTimings::new(); + let wait_timings = timings.clone(); + let stream = futures::stream::once(async move { + let waited = Duration::from_millis(5); + std::thread::sleep(waited); + wait_timings.record_auction_wait(AuctionWaitPlacement::InStream, waited); + bytes::Bytes::from_static(b"") + }); + let body = EdgeBody::stream(stream); + + let (_counting, drive_result) = drive_streaming_body(body, Vec::new(), &timings); + drive_result.expect("streaming a well-formed body should not fail"); + + let snapshot = timings.snapshot(); + assert_eq!( + snapshot.auction_wait_placement, + Some(AuctionWaitPlacement::InStream), + "should preserve the placement recorded from inside the polled body" + ); + let auction_wait_ms = snapshot + .auction_wait_ms + .expect("should record the auction wait"); + let stream_ms = snapshot.stream_ms.expect("should record the stream drive"); + assert!( + stream_ms >= auction_wait_ms, + "the drive's Phase::Stream span must cover the in-stream auction wait: \ + stream_ms={stream_ms} auction_wait_ms={auction_wait_ms}" + ); + } + + #[test] + fn classify_stream_delivery_treats_bytes_written_before_an_error_as_partial() { + let err = Report::new(TrustedServerError::Proxy { + message: "boom".to_string(), + }); + assert_eq!( + classify_stream_delivery(&Err(err), 42), + DeliveryResult::Partial, + "bytes already on the wire before a stream error is a truncated delivery" + ); + } + + #[test] + fn classify_stream_delivery_treats_an_error_with_no_bytes_as_error() { + let err = Report::new(TrustedServerError::Proxy { + message: "boom".to_string(), + }); + assert_eq!( + classify_stream_delivery(&Err(err), 0), + DeliveryResult::Error, + "a failure before any byte reached the client is a clean failure, not a truncation" + ); + } + + #[test] + fn classify_stream_delivery_treats_ok_as_complete() { + assert_eq!( + classify_stream_delivery(&Ok(()), 123), + DeliveryResult::Complete + ); + } + + #[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".to_owned(), + publisher_domain: "test-publisher.com".to_owned(), + access_sample_rate: 1.0, + access_telemetry_enabled: true, + }, + ); + assert!( + timings.snapshot().request_elapsed_ms.is_some(), + "request_elapsed should 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..7bd577363 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,12 @@ impl Middleware for FinalizeResponseMiddleware { || FastlyRequestContext::get(ctx.request()).and_then(|c| c.client_ip), |info| info.client_ip, ); + let timings = ctx + .request() + .extensions() + .get::() + .cloned() + .unwrap_or_default(); let mut response = match next.run(ctx).await { Ok(r) => r, @@ -80,13 +87,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 +163,20 @@ impl Middleware for AuthMiddleware { // Shared geo resolution helper // --------------------------------------------------------------------------- -/// Resolves geo for a response, skipping the lookup for 401 responses. +/// Resolves geo for a response, skipping the lookup for 401 responses and +/// reusing a request-phase lookup when one was already carried. /// -/// Returns `None` for authentication rejections (401) without calling `lookup_geo` -/// to avoid unnecessary work and exposing geo data to unauthenticated callers. -/// All other responses call `lookup_geo` and return its result. +/// Returns `None` for authentication rejections (401) without consulting +/// `carried` or calling `lookup_geo`, to avoid unnecessary work and exposing +/// geo data to unauthenticated callers. Otherwise dispatches on `carried`: +/// a [`GeoLookupState::Resolved`] value is reused as-is, a +/// [`GeoLookupState::Attempted`] value is treated as no geo info without +/// retrying the lookup, and [`GeoLookupState::NotAttempted`] falls back to +/// calling `lookup_geo`. /// /// Used by both [`FinalizeResponseMiddleware`] and the entry-point finalization -/// in `main.rs` so the 401-skip rule is defined in one place. +/// in `main.rs` so the 401-skip rule and the dedupe rule are each defined in +/// one place. /// /// # Parity note /// @@ -162,8 +186,29 @@ impl Middleware for AuthMiddleware { /// is intentionally more conservative: geo data is not sent to any /// unauthenticated caller regardless of whether the 401 originated from this /// server or the upstream origin. +/// 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); +} + pub(crate) fn resolve_geo_for_response( response: &Response, + carried: &GeoLookupState, client_ip: Option, lookup_geo: F, ) -> Option @@ -171,9 +216,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 +298,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 +373,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 +788,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 +930,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..bd02652e6 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/secret-store/ + /// body-size-limit derivation, but points at `access_dataset` and + /// `access_token_secret` instead of the auction pair, so access-log + /// emission never shares a datasource or token with auction telemetry + /// even though both configs come from the same [`TinybirdSettings`]. + pub(crate) fn from_access_config(config: TinybirdSettings) -> Self { + let uri = tinybird_events_uri(&config.api_host, &config.access_dataset); + let backend_spec = tinybird_backend_spec(&config.api_host); + Self { + api_host: config.api_host, + dataset: config.access_dataset, + append_token: config + .access_token_secret + .expect("should contain a resolved Tinybird access token when enabled"), + uri, + backend_spec, + max_body_bytes: config.max_body_bytes, + } + } } impl FastlyTinybirdAuctionTelemetrySink { @@ -182,6 +214,132 @@ 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 +/// access-log APPEND token cannot be loaded, the backend cannot be registered, +/// the request cannot be built or sent, or the Tinybird Events API responds +/// with a non-2xx status. +pub(crate) async fn emit_access_event( + client: &dyn PlatformHttpClient, + target: &TinybirdEventsTarget, + 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::info!( + "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 +464,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 +508,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 +624,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("example-access-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 +846,143 @@ 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() { + // `ts_secrets`/`tinybird_access_append_token` is seeded in + // fastly.toml's `[local_server.secret_stores]` fixture (value + // "test-tinybird-access-append-token"), so `emit_access_event` can + // load a real token through Viceroy without a secret-store test + // double — the same fixture backs the auction-token secret used + // above. + let target = TinybirdEventsTarget::from_access_config(enabled_config()); + let http_client = RecordingHttpClient::respond_with(202); + let row = r#"{"status":200}"#.to_owned(); + + futures::executor::block_on(emit_access_event(&http_client, &target, row.clone())) + .expect("should accept a 202 response"); + + let requests = http_client + .requests + .lock() + .expect("should lock recorded requests"); + assert_eq!(requests.len(), 1, "should send exactly one request"); + assert_eq!( + requests[0].uri, + "https://api.us-east.aws.tinybird.co/v0/events?name=access_logs_raw" + ); + assert_eq!(requests[0].method, Method::POST.to_string()); + assert_eq!( + header_value(&requests[0].headers, header::AUTHORIZATION.as_str()), + Some("Bearer example-access-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..b9e0a9eab 100644 --- a/crates/trusted-server-adapter-spin/src/app.rs +++ b/crates/trusted-server-adapter-spin/src/app.rs @@ -48,7 +48,8 @@ use trusted_server_core::settings::Settings; use trusted_server_core::settings_data::{default_config_key, default_secret_store_name}; use crate::middleware::{ - AuthMiddleware, FinalizeResponseMiddleware, NormalizeMiddleware, SanitizeRequestMiddleware, + AuthMiddleware, FinalizeResponseMiddleware, NormalizeMiddleware, RequestTimingMiddleware, + SanitizeRequestMiddleware, }; use crate::platform::build_runtime_services; #[cfg(all(feature = "spin", target_arch = "wasm32"))] @@ -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::new()) .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..d31c6ad7e 100644 --- a/crates/trusted-server-adapter-spin/src/middleware.rs +++ b/crates/trusted-server-adapter-spin/src/middleware.rs @@ -8,6 +8,7 @@ use edgezero_core::middleware::{Middleware, Next}; use trusted_server_core::auth::enforce_basic_auth; use trusted_server_core::constants::HEADER_X_GEO_INFO_AVAILABLE; use trusted_server_core::http_util::sanitize_trusted_client_ip_headers; +use trusted_server_core::request_timing::RequestTimings; use trusted_server_core::settings::Settings; // --------------------------------------------------------------------------- @@ -46,6 +47,40 @@ impl Middleware for SanitizeRequestMiddleware { } } +// --------------------------------------------------------------------------- +// RequestTimingMiddleware +// --------------------------------------------------------------------------- + +/// Attaches the server request clock consumed by core timing instrumentation. +/// +/// This adapter does not emit `Server-Timing`; the collector keeps timing +/// origins consistent for request-scoped consumers such as GPT diagnostics. +/// Health checks remain outside timing collection on every adapter. +#[derive(Default)] +pub struct RequestTimingMiddleware; + +impl RequestTimingMiddleware { + /// Creates a new [`RequestTimingMiddleware`]. + #[must_use] + pub fn new() -> Self { + Self + } +} + +#[async_trait(?Send)] +impl Middleware for RequestTimingMiddleware { + async fn handle(&self, mut ctx: RequestContext, next: Next<'_>) -> Result { + if ctx.request().uri().path() != "/health" + && ctx.request().extensions().get::().is_none() + { + ctx.request_mut() + .extensions_mut() + .insert(RequestTimings::new()); + } + next.run(ctx).await + } +} + // --------------------------------------------------------------------------- // FinalizeResponseMiddleware // --------------------------------------------------------------------------- @@ -55,9 +90,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`] and ahead of [`AuthMiddleware`] +/// so that every outgoing response — including auth-rejected ones — carries a +/// consistent set of headers. pub struct FinalizeResponseMiddleware { settings: Arc, } @@ -207,10 +242,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 +253,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 +355,34 @@ mod tests { ); } + #[test] + fn request_timing_middleware_attaches_a_collector_except_for_health() { + for (path, expected) in [("/test", true), ("/health", false)] { + let observed = Arc::new(Mutex::new(None)); + let handler_observed = Arc::clone(&observed); + let handler = Arc::new(move |ctx: RequestContext| { + let handler_observed = Arc::clone(&handler_observed); + async move { + *handler_observed.lock().expect("should lock observation") = + Some(ctx.request().extensions().get::().is_some()); + Ok::(empty_response()) + } + }); + + block_on( + RequestTimingMiddleware::new() + .handle(ctx_for_path(path), Next::new(&[], &*handler)), + ) + .expect("should run timing middleware"); + + assert_eq!( + *observed.lock().expect("should lock observation"), + Some(expected), + "collector presence should match timing policy for {path}" + ); + } + } + #[test] fn sanitize_middleware_strips_configured_trust_headers_before_routing() { let mut settings = settings_with_response_headers(vec![]); diff --git a/crates/trusted-server-cli/src/commands/audit/browser.rs b/crates/trusted-server-cli/src/commands/audit/browser.rs index fd79155f0..50bda2c5f 100644 --- a/crates/trusted-server-cli/src/commands/audit/browser.rs +++ b/crates/trusted-server-cli/src/commands/audit/browser.rs @@ -48,6 +48,8 @@ const NAVIGATION_TIMEOUT: Duration = Duration::from_secs(30); const MAX_EVIDENCE_ENTRIES: usize = 128; /// Hard cap on the UTF-8 JSON payload before CDP transfers it back to Rust. const MAX_EVIDENCE_PAYLOAD_BYTES: usize = 1024 * 1024; +/// Hard cap on browser startup, allowing cold launches on shared CI runners. +const BROWSER_LAUNCH_TIMEOUT: Duration = Duration::from_secs(60); /// Hard cap on browser teardown so a wedged Chrome cannot hang the audit. const BROWSER_CLOSE_TIMEOUT: Duration = Duration::from_secs(5); @@ -151,7 +153,8 @@ pub(crate) fn build_browser_config( ) -> Result { let mut builder = BrowserConfig::builder() .chrome_executable(options.chrome) - .user_data_dir(options.profile_dir); + .user_data_dir(options.profile_dir) + .launch_timeout(BROWSER_LAUNCH_TIMEOUT); if !options.accept_invalid_certs { builder = builder.respect_https_errors(); } diff --git a/crates/trusted-server-cli/tests/config_store_defaults.rs b/crates/trusted-server-cli/tests/config_store_defaults.rs index 23c5f86e9..564697487 100644 --- a/crates/trusted-server-cli/tests/config_store_defaults.rs +++ b/crates/trusted-server-cli/tests/config_store_defaults.rs @@ -133,8 +133,10 @@ fn config_push_resolves_the_physical_name_and_explicit_key() { ); } +// EdgeZero's pinned store-selector revision makes the runtime key override +// redirect Axum config pushes even without `--key`. This differs from v0.0.8. #[test] -fn config_push_does_not_use_the_runtime_key_override_without_the_key_flag() { +fn config_push_follows_the_runtime_key_override_without_the_key_flag() { let project = project(); let key_var = format!( "EDGEZERO__STORES__CONFIG__{}__KEY", @@ -145,7 +147,8 @@ fn config_push_does_not_use_the_runtime_key_override_without_the_key_flag() { let entries = stored_entries(&project); assert_eq!(entries.len(), 1); assert!( - entries.contains_key(CONFIG_BLOB_KEY), - "runtime-only key override should not move the CLI's write destination" + entries.contains_key("active_config"), + "runtime key override should move the CLI's write destination; got keys: {:?}", + entries.keys().collect::>() ); } diff --git a/crates/trusted-server-core/examples/local_dev_config.rs b/crates/trusted-server-core/examples/local_dev_config.rs new file mode 100644 index 000000000..acbb61b6c --- /dev/null +++ b/crates/trusted-server-core/examples/local_dev_config.rs @@ -0,0 +1,129 @@ +//! Generate a ready-to-use local dev config envelope for the Axum adapter. +//! +//! Reads `trusted-server.example.toml`, replaces the placeholder secrets with +//! random values, flips the flags a local smoke test needs, validates the +//! result through [`trusted_server_core::settings::Settings::from_toml`], and +//! prints the blob envelope JSON that the Axum adapter's +//! `TRUSTED_SERVER_CONFIG_{STORE}_{KEY}` environment variable expects. With +//! the default store and key both named `trusted_server_config`, the +//! concrete variable resolves (not a typo) to +//! `TRUSTED_SERVER_CONFIG_TRUSTED_SERVER_CONFIG_TRUSTED_SERVER_CONFIG`. +//! +//! The random values are time-and-pid seeded, not cryptographic. This tool +//! exists for throwaway local test instances only; never use its output for a +//! deployed service. +//! +//! Usage: +//! +//! ```text +//! cargo run -p trusted-server-core --example local_dev_config \ +//! --target -- [origin-url] [--realistic] +//! ``` +//! +//! `origin-url` defaults to `https://www.example.com`. By default every +//! response is forced `Cache-Control: private, no-store` so the Server-Timing +//! header is visible on all routes; pass `--realistic` to keep the origin's +//! own cache policy instead. + +use std::time::{SystemTime, UNIX_EPOCH}; + +/// Deliberately non-cryptographic generator for local placeholder secrets. +struct WeakRandom(u64); + +impl WeakRandom { + fn from_environment() -> Self { + let nanos = SystemTime::now() + .duration_since(UNIX_EPOCH) + .expect("should compute epoch time") + .subsec_nanos() as u64; + let secs = SystemTime::now() + .duration_since(UNIX_EPOCH) + .expect("should compute epoch time") + .as_secs(); + let pid = std::process::id() as u64; + Self(nanos ^ (secs << 20) ^ (pid << 40) ^ 0x9e37_79b9_7f4a_7c15) + } + + fn next(&mut self) -> u64 { + let mut x = self.0; + x ^= x << 13; + x ^= x >> 7; + x ^= x << 17; + self.0 = x; + x + } + + fn hex(&mut self, chars: usize) -> String { + let mut out = String::with_capacity(chars); + while out.len() < chars { + out.push_str(&format!("{:016x}", self.next())); + } + out.truncate(chars); + out + } +} + +#[allow(clippy::print_stdout, clippy::print_stderr)] +fn main() { + let args: Vec = std::env::args().skip(1).collect(); + let realistic = args.iter().any(|a| a == "--realistic"); + let origin = args + .iter() + .find(|a| !a.starts_with("--")) + .cloned() + .unwrap_or_else(|| "https://www.example.com".to_string()); + + let template = std::fs::read_to_string("trusted-server.example.toml") + .expect("should read trusted-server.example.toml from the repo root"); + + let mut random = WeakRandom::from_environment(); + let mut config = template + .replace( + "password = \"replace-with-admin-password-32-bytes\"", + &format!("password = \"{}\"", random.hex(48)), + ) + .replace( + "proxy_secret = \"change-me-proxy-secret\"", + &format!("proxy_secret = \"{}\"", random.hex(48)), + ) + .replace( + "passphrase = \"trusted-server-placeholder-secret\"", + &format!("passphrase = \"{}\"", random.hex(48)), + ) + .replace( + "server_timing_enabled = false", + "server_timing_enabled = true", + ); + + let origin_line = config + .lines() + .find(|line| line.starts_with("origin_url = ")) + .expect("should find the origin_url line in the template") + .to_string(); + config = config.replace(&origin_line, &format!("origin_url = \"{origin}\"")); + + if !realistic { + config = config.replace( + "# [response_headers]", + "[response_headers]\n\"Cache-Control\" = \"private, no-store\"", + ); + } + + let settings = trusted_server_core::settings::Settings::from_toml(&config) + .expect("should validate the generated local config"); + let data = serde_json::to_value(&settings).expect("should serialize settings"); + let generated_at = SystemTime::now() + .duration_since(UNIX_EPOCH) + .expect("should compute epoch time") + .as_secs() + .to_string(); + let envelope = edgezero_core::blob_envelope::BlobEnvelope::new(data, generated_at); + println!( + "{}", + serde_json::to_string(&envelope).expect("should serialize the envelope") + ); + eprintln!( + "local dev envelope generated: origin={origin} force_private={}", + !realistic + ); +} diff --git a/crates/trusted-server-core/src/access_telemetry.rs b/crates/trusted-server-core/src/access_telemetry.rs new file mode 100644 index 000000000..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..355d7d400 100644 --- a/crates/trusted-server-core/src/auction/endpoints.rs +++ b/crates/trusted-server-core/src/auction/endpoints.rs @@ -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,16 @@ 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 = parts + .extensions + .get::() + .cloned() + .unwrap_or_default(); let body_bytes = body.into_bytes().unwrap_or_default(); if body_bytes.len() > MAX_AUCTION_BODY_SIZE { return Response::builder() @@ -362,10 +373,17 @@ pub async fn handle_auction( ec_context, ); + timings.set_auction_id(observation.auction_id); + // Run the auction + timings.mark_auction_dispatched(); let result = match orchestrator.run_auction(&auction_request, &context).await { - Ok(result) => result, + Ok(result) => { + timings.mark_auction_resolved(); + result + } Err(err) => { + timings.mark_auction_resolved(); let elapsed_ms = observation.elapsed_ms(); emit_auction_events_best_effort_lazy(services, || { build_auction_events( @@ -410,6 +428,10 @@ pub async fn handle_auction( } }; + // Targeting is available to the caller: for this route the response body + // is the commit, since there is no page state to write into. + timings.mark_auction_committed(); + emit_auction_events_best_effort_lazy(services, || { build_auction_events( observation, diff --git a/crates/trusted-server-core/src/config.rs b/crates/trusted-server-core/src/config.rs index 79f100e2f..9ceca96b4 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 { @@ -830,6 +842,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..36224927b 100644 --- a/crates/trusted-server-core/src/config_payload.rs +++ b/crates/trusted-server-core/src/config_payload.rs @@ -72,16 +72,25 @@ 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 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 !enabled || !auction_enabled { + tinybird.remove("auction_token_secret"); + } + if !enabled || !access_enabled { + tinybird.remove("access_token_secret"); + } } if let Some(partners) = data 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/aps.rs b/crates/trusted-server-core/src/integrations/aps.rs index 4f45fbeb9..53b30ed6f 100644 --- a/crates/trusted-server-core/src/integrations/aps.rs +++ b/crates/trusted-server-core/src/integrations/aps.rs @@ -78,42 +78,54 @@ const APS_RENDERER_DOCUMENT: &str = r#" var match=/^#tsaps=([A-Za-z0-9_-]{22,128})$/.exec(location.hash); var expected=match&&match[1]; try{history.replaceState(null,'',location.pathname+location.search);}catch(_error){} -if(!expected)return; +var reported=false; +function report(reason,nonce){ + if(reported)return; + reported=true; + try{parent.postMessage({message:'trusted-server/aps/renderer-failed',nonce:nonce,reason:reason},'*');}catch(_error){} +} +if(!expected){report('bad_hash');return;} function keys(value,expectedKeys){ if(!value||typeof value!=='object'||Array.isArray(value))return false; var actual=Object.keys(value).sort(); return actual.length===expectedKeys.length&&actual.every(function(key,index){return key===expectedKeys[index];}); } -function validRenderer(renderer){ +function rendererProblem(renderer){ if(!keys(renderer,['aaxResponse','accountId','bidId','creativeId','creativeUrl','height','tagType','type','version','width'])&& - !keys(renderer,['aaxResponse','accountId','bidId','creativeUrl','height','tagType','type','version','width']))return false; - if(renderer.type!=='aps'||renderer.version!==1||typeof renderer.accountId!=='string'||!renderer.accountId||new TextEncoder().encode(renderer.accountId).length>1024)return false; - if(typeof renderer.bidId!=='string'||!renderer.bidId||!Number.isInteger(renderer.width)||renderer.width<=0||!Number.isInteger(renderer.height)||renderer.height<=0)return false; - if(Object.prototype.hasOwnProperty.call(renderer,'creativeId')&&(typeof renderer.creativeId!=='string'||!renderer.creativeId||new TextEncoder().encode(renderer.creativeId).length>1024))return false; - if(renderer.tagType!=='iframe'&&renderer.tagType!=='script')return false; - if(typeof renderer.creativeUrl!=='string'||new TextEncoder().encode(renderer.creativeUrl).length>4096)return false; - if(typeof renderer.aaxResponse!=='string'||!renderer.aaxResponse||renderer.aaxResponse.length>349528)return false; + !keys(renderer,['aaxResponse','accountId','bidId','creativeUrl','height','tagType','type','version','width']))return 'descriptor_keys'; + if(renderer.type!=='aps'||renderer.version!==1||typeof renderer.accountId!=='string'||!renderer.accountId||new TextEncoder().encode(renderer.accountId).length>1024)return 'descriptor_fields'; + if(typeof renderer.bidId!=='string'||!renderer.bidId||!Number.isInteger(renderer.width)||renderer.width<=0||!Number.isInteger(renderer.height)||renderer.height<=0)return 'descriptor_fields'; + if(Object.prototype.hasOwnProperty.call(renderer,'creativeId')&&(typeof renderer.creativeId!=='string'||!renderer.creativeId||new TextEncoder().encode(renderer.creativeId).length>1024))return 'descriptor_fields'; + if(renderer.tagType!=='iframe'&&renderer.tagType!=='script')return 'descriptor_fields'; + if(typeof renderer.creativeUrl!=='string'||new TextEncoder().encode(renderer.creativeUrl).length>4096)return 'descriptor_fields'; + if(typeof renderer.aaxResponse!=='string'||!renderer.aaxResponse||renderer.aaxResponse.length>349528)return 'descriptor_fields'; try{ var url=new URL(renderer.creativeUrl); - if(url.protocol!=='https:'||url.username||url.password)return false; + if(url.protocol!=='https:'||url.username||url.password)return 'descriptor_envelope'; var binary=atob(renderer.aaxResponse); - if(binary.length>262144||btoa(binary)!==renderer.aaxResponse)return false; + if(binary.length>262144||btoa(binary)!==renderer.aaxResponse)return 'descriptor_envelope'; var bytes=Uint8Array.from(binary,function(character){return character.charCodeAt(0);}); var decoded=JSON.parse(new TextDecoder('utf-8',{fatal:true}).decode(bytes)); - if(!keys(decoded,['seatbid'])||!Array.isArray(decoded.seatbid)||decoded.seatbid.length!==1)return false; + if(!keys(decoded,['seatbid'])||!Array.isArray(decoded.seatbid)||decoded.seatbid.length!==1)return 'descriptor_envelope'; var seat=decoded.seatbid[0]; - if(!keys(seat,['bid'])||!Array.isArray(seat.bid)||seat.bid.length!==1)return false; + if(!keys(seat,['bid'])||!Array.isArray(seat.bid)||seat.bid.length!==1)return 'descriptor_envelope'; var bid=seat.bid[0]; - if(!keys(bid,['ext','h','id','price','w'])||!keys(bid.ext,['creativeurl','tagtype']))return false; - return bid.id===renderer.bidId&&bid.w===renderer.width&&bid.h===renderer.height&& + if(!keys(bid,['ext','h','id','price','w'])||!keys(bid.ext,['creativeurl','tagtype']))return 'descriptor_envelope'; + if(bid.id===renderer.bidId&&bid.w===renderer.width&&bid.h===renderer.height&& bid.ext.creativeurl===renderer.creativeUrl&&bid.ext.tagtype===renderer.tagType&& - typeof bid.price==='number'&&Number.isFinite(bid.price)&&bid.price>=0; - }catch(_error){return false;} + typeof bid.price==='number'&&Number.isFinite(bid.price)&&bid.price>=0)return undefined; + return 'descriptor_envelope'; + }catch(_error){return 'descriptor_envelope';} } function receive(event){ - if(event.source!==parent)return; var message=event.data; - if(!keys(message,['nonce','renderer'])||message.nonce!==expected||!validRenderer(message.renderer))return; + // Stay silent for traffic that is not shaped like the render handshake, so an + // unrelated sender cannot consume this frame's single report. + if(!keys(message,['nonce','renderer']))return; + if(event.source!==parent){report('source_mismatch');return;} + if(message.nonce!==expected){report('nonce_mismatch');return;} + var problem=rendererProblem(message.renderer); + if(problem){report(problem,message.nonce);return;} removeEventListener('message',receive); var acceptedNonce=expected; expected=''; @@ -128,7 +140,7 @@ function receive(event){ var script=document.createElement('script'); script.src='https://client.aps.amazon-adsystem.com/prebid-creative.js'; script.onload=function(){parent.postMessage({message:'trusted-server/aps/renderer-ready',nonce:acceptedNonce},'*');}; - script.onerror=function(){parent.postMessage({message:'trusted-server/aps/renderer-failed',nonce:acceptedNonce},'*');}; + script.onerror=function(){report('amazon_script_error',acceptedNonce);}; document.head.appendChild(script); } addEventListener('message',receive); @@ -3308,4 +3320,41 @@ mod tests { assert!(APS_RENDERER_CSP.contains("sandbox allow-forms")); assert!(!APS_RENDERER_CSP.contains("allow-same-origin")); } + + #[test] + fn renderer_document_reports_a_reason_for_every_silent_guard() { + for reason in [ + "bad_hash", + "source_mismatch", + "nonce_mismatch", + "descriptor_keys", + "descriptor_fields", + "descriptor_envelope", + "amazon_script_error", + ] { + assert!( + APS_RENDERER_DOCUMENT.contains(reason), + "renderer document should report a `{reason}` reason instead of returning silently" + ); + } + + // Reasons travel on the existing failure message rather than a new channel. + assert!( + APS_RENDERER_DOCUMENT.contains("reason:reason"), + "should attach the reason to the failure message" + ); + + // A reason is a fixed category, never a copy of the rejected descriptor. + assert!(!APS_RENDERER_DOCUMENT.contains("JSON.stringify(renderer)")); + assert!(!APS_RENDERER_DOCUMENT.contains("reason:message")); + + // Reporting is one-shot so a hostile sender cannot flood the parent. + assert!( + APS_RENDERER_DOCUMENT.contains("if(reported)return"), + "should report at most one reason per frame" + ); + + // A foreign sender is answered through the parent, never the sender. + assert!(!APS_RENDERER_DOCUMENT.contains("event.source.postMessage")); + } } 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 47c521e61..c137fd855 100644 --- a/crates/trusted-server-core/src/integrations/registry.rs +++ b/crates/trusted-server-core/src/integrations/registry.rs @@ -691,7 +691,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 @@ -837,7 +847,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("/*") { @@ -934,6 +948,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 @@ -1009,7 +1044,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. @@ -1322,7 +1357,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(); @@ -1331,7 +1366,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/integrations/sourcepoint.rs b/crates/trusted-server-core/src/integrations/sourcepoint.rs index 44979c296..d22cc4ffe 100644 --- a/crates/trusted-server-core/src/integrations/sourcepoint.rs +++ b/crates/trusted-server-core/src/integrations/sourcepoint.rs @@ -45,10 +45,11 @@ use crate::settings::{IntegrationConfig, Settings}; const SOURCEPOINT_INTEGRATION_ID: &str = "sourcepoint"; const SOURCEPOINT_CDN_HOST: &str = "cdn.privacy-mgmt.com"; const SOURCEPOINT_CDN_PREFIX: &str = "/integrations/sourcepoint/cdn"; +const SOURCEPOINT_SITE_DATA_PATH: &str = "/mms/v2/get_site_data"; -/// Maximum response body size (5 MB) that will be read into memory for -/// JavaScript rewriting. Responses larger than this are passed through -/// unmodified to avoid unbounded memory consumption. +/// Maximum input body size (5 MiB) collected for JavaScript or HTML rewriting. +/// Declared larger bodies pass through without collection. Bodies that exceed +/// this limit during collection return an integration error (502). const MAX_REWRITE_BODY_SIZE: u64 = 5 * 1024 * 1024; /// Sourcepoint cookie names that are safe to round-trip to the upstream CDN. @@ -609,7 +610,10 @@ impl SourcepointIntegration { /// is a conservative preflight — false negatives just mean we skip the /// `Accept-Encoding: identity` optimisation for that request. fn is_likely_javascript_path(path: &str) -> bool { - path.ends_with(".js") || path.ends_with(".mjs") || path.starts_with("/unified/") + path.ends_with(".js") + || path.ends_with(".mjs") + || path.starts_with("/unified/") + || path == SOURCEPOINT_SITE_DATA_PATH } /// Returns `true` when the response `Content-Type` looks like JavaScript. @@ -650,9 +654,22 @@ impl SourcepointIntegration { } } - fn rewrite_javascript_response(&self, response: &mut Response, rewritten: String) { + fn rewrite_javascript_response( + &self, + response: &mut Response, + rewritten: String, + target_path: &str, + forwarded_cookies: bool, + ) { self.finalize_rewritten_body(response, rewritten, "application/javascript; charset=utf-8"); + // Site data is a dynamic API response despite its JavaScript content + // type. Preserve its upstream cache policy and cookie-aware defaults. + if target_path == SOURCEPOINT_SITE_DATA_PATH { + self.apply_cache_headers(response, forwarded_cookies); + return; + } + // Rewritten JavaScript bundles are static, versioned files (hashed chunk // names, `/unified/4.40.1/…` paths), so we apply a fixed public cache // policy regardless of what upstream sent. This intentionally diverges @@ -870,9 +887,15 @@ impl IntegrationProxy for SourcepointIntegration { None, )?; + // Keep the body streaming where supported so the rewrite collector + // enforces its limit before the adapter buffers the entire response. + let mut platform_request = PlatformHttpRequest::new(proxy_req, backend_name); + if services.http_client().supports_streaming_responses() { + platform_request = platform_request.with_stream_response(); + } let mut response = services .http_client() - .send(PlatformHttpRequest::new(proxy_req, backend_name)) + .send(platform_request) .await .change_context(Self::error("Sourcepoint upstream request failed"))? .response; @@ -930,27 +953,21 @@ impl IntegrationProxy for SourcepointIntegration { .and_then(|v| v.to_str().ok()) .and_then(|s| s.parse::().ok()); - match content_length { - Some(len) if len > MAX_REWRITE_BODY_SIZE => { - log::warn!( - "Sourcepoint: response body for {path} exceeds {} bytes \ - (Content-Length: {len}), skipping rewrite (reason: known_length_too_large)", - MAX_REWRITE_BODY_SIZE - ); - self.apply_cache_headers(&mut response, forwarded_cookies); - return Ok(response); - } - None => { - log::warn!( - "Sourcepoint: no Content-Length for {path}, \ - skipping rewrite to avoid unbounded memory read (reason: missing_content_length)" - ); - self.apply_cache_headers(&mut response, forwarded_cookies); - return Ok(response); - } - Some(_) => {} + if let Some(len) = content_length + && len > MAX_REWRITE_BODY_SIZE + { + log::warn!( + "Sourcepoint: response body for {path} exceeds {} bytes \ + (Content-Length: {len}), skipping rewrite (reason: known_length_too_large)", + MAX_REWRITE_BODY_SIZE + ); + self.apply_cache_headers(&mut response, forwarded_cookies); + return Ok(response); } + // Content-Length is optional and advisory. Stop at the actual + // byte limit even when the header is absent or understates the + // size. Overflow discards the partial body and returns a 502. let (resp_parts, resp_body) = response.into_parts(); let body_bytes = collect_response_bounded( resp_body, @@ -975,7 +992,12 @@ impl IntegrationProxy for SourcepointIntegration { }; if response_is_javascript { let rewritten = Self::rewrite_script_content(&body); - self.rewrite_javascript_response(&mut response, rewritten); + self.rewrite_javascript_response( + &mut response, + rewritten, + target_path, + forwarded_cookies, + ); } else { let rewritten = Self::rewrite_html_content(&body); self.rewrite_html_response(&mut response, rewritten, forwarded_cookies); @@ -1085,9 +1107,539 @@ impl IntegrationHeadInjector for SourcepointIntegration { #[cfg(test)] mod tests { use super::*; + use crate::error::IntoHttpResponse as _; use crate::integrations::{IntegrationDocumentState, IntegrationRegistry}; + use crate::platform::test_support::{StubHttpClient, build_services_with_http_client}; + use crate::platform::{ + PlatformError, PlatformHttpClient, PlatformPendingRequest, PlatformResponse, + PlatformSelectResult, + }; use crate::test_support::tests::create_test_settings; use serde_json::json; + use std::sync::atomic::{AtomicUsize, Ordering}; + + const TEST_CHUNK_SIZE: usize = 8192; + + struct StreamingHttpClient { + stub: StubHttpClient, + reads: Arc, + } + + impl StreamingHttpClient { + fn new() -> Self { + Self { + stub: StubHttpClient::new(), + reads: Arc::new(AtomicUsize::new(0)), + } + } + } + + #[async_trait(?Send)] + impl PlatformHttpClient for StreamingHttpClient { + fn supports_streaming_responses(&self) -> bool { + true + } + + async fn send( + &self, + request: PlatformHttpRequest, + ) -> Result> { + let mut response = self.stub.send(request).await?; + let body = std::mem::replace(response.response.body_mut(), EdgeBody::empty()); + let EdgeBody::Once(bytes) = body else { + panic!("should receive a buffered stub body"); + }; + let reads = Arc::clone(&self.reads); + let chunks = futures::stream::unfold((bytes, 0), move |(bytes, offset)| { + reads.fetch_add(1, Ordering::Relaxed); + let end = (offset + TEST_CHUNK_SIZE).min(bytes.len()); + futures::future::ready( + (offset < bytes.len()).then(|| (bytes.slice(offset..end), (bytes, end))), + ) + }); + *response.response.body_mut() = EdgeBody::stream(chunks); + Ok(response) + } + + async fn send_async( + &self, + request: PlatformHttpRequest, + ) -> Result> { + self.stub.send_async(request).await + } + + async fn select( + &self, + pending_requests: Vec, + ) -> Result> { + self.stub.select(pending_requests).await + } + } + + #[test] + fn handle_rewrites_streamed_javascript_without_content_length() { + futures::executor::block_on(async { + let settings = create_test_settings(); + let integration = SourcepointIntegration::new(Arc::new(config(true))); + let client = Arc::new(StreamingHttpClient::new()); + let input = format!(r#"var api="https://{SOURCEPOINT_CDN_HOST}/consent/tcfv2";"#); + client.stub.push_response_with_headers( + 200, + input.into_bytes(), + vec![("content-type", "application/javascript")], + ); + let services = build_services_with_http_client(client.clone()); + + let response = integration + .handle( + &settings, + &services, + make_req( + Method::GET, + "https://publisher.example.com/integrations/sourcepoint/cdn/wrapper.js", + ), + ) + .await + .expect("should proxy JavaScript without Content-Length"); + + assert_eq!( + response + .into_body() + .into_bytes_bounded(1024) + .await + .expect("should collect JavaScript response") + .as_ref(), + br#"var api="/integrations/sourcepoint/cdn/consent/tcfv2";"#, + "should rewrite a streamed CDN URL without Content-Length" + ); + assert_eq!( + client.stub.recorded_stream_response_flags(), + vec![true], + "should request streaming before collecting the upstream body" + ); + }); + } + + #[test] + fn handle_rewrites_streamed_html_without_content_length() { + futures::executor::block_on(async { + let settings = create_test_settings(); + let integration = SourcepointIntegration::new(Arc::new(config(true))); + let client = Arc::new(StreamingHttpClient::new()); + client.stub.push_response_with_headers( + 200, + br#""#.to_vec(), + vec![("content-type", "text/html"), ("cache-control", "no-store")], + ); + let services = build_services_with_http_client(client.clone()); + + let response = integration + .handle( + &settings, + &services, + make_req(Method::GET, "https://publisher.example.com/integrations/sourcepoint/cdn/us_pm/index.html"), + ) + .await + .expect("should proxy HTML without Content-Length"); + + assert_eq!( + get_header_str(&response, header::CACHE_CONTROL), + Some("no-store"), + "should preserve upstream HTML cache policy" + ); + assert_eq!( + response.into_body().into_bytes_bounded(1024).await.expect("should collect HTML response").as_ref(), + br#""#, + "should rewrite streamed privacy-manager assets without Content-Length" + ); + }); + } + + #[test] + fn handle_accepts_exact_rewrite_limit_and_stops_reading_on_overflow() { + futures::executor::block_on(async { + let settings = create_test_settings(); + let integration = SourcepointIntegration::new(Arc::new(config(true))); + let limit = MAX_REWRITE_BODY_SIZE as usize; + for content_type in ["application/javascript", "text/html"] { + for declared_length in [None, Some("1")] { + for extra_bytes in [0, 1, TEST_CHUNK_SIZE * 2] { + let client = Arc::new(StreamingHttpClient::new()); + let mut headers = vec![("content-type", content_type)]; + if let Some(length) = declared_length { + headers.push(("content-length", length)); + } + client.stub.push_response_with_headers( + 200, + vec![b' '; limit + extra_bytes], + headers, + ); + let services = build_services_with_http_client(client.clone()); + + let result = integration.handle( + &settings, + &services, + make_req(Method::GET, "https://publisher.example.com/integrations/sourcepoint/cdn/asset"), + ).await; + + if extra_bytes == 0 { + let response = result.expect("should accept exactly 5 MiB"); + assert!( + response.headers().get(header::CONTENT_LENGTH).is_none(), + "should remove the advisory length after rewriting" + ); + assert_eq!( + take_body_bytes(response).len(), + limit, + "should retain the entire body at the limit" + ); + } else { + let error = + result.expect_err("should reject an oversized streamed body"); + assert_eq!( + error.current_context().status_code(), + StatusCode::BAD_GATEWAY, + "should report upstream overflow as 502" + ); + assert!( + matches!(error.current_context(), TrustedServerError::Integration { integration, message } if integration == SOURCEPOINT_INTEGRATION_ID && message.contains("exceeds")), + "should identify Sourcepoint response overflow" + ); + } + assert_eq!( + client.reads.load(Ordering::Relaxed), + limit / TEST_CHUNK_SIZE + 1, + "should stop at EOF or the first overflowing chunk without draining the stream" + ); + } + } + } + }); + } + + #[test] + fn handle_passes_through_declared_oversize_without_reading() { + futures::executor::block_on(async { + let settings = create_test_settings(); + let integration = SourcepointIntegration::new(Arc::new(config(true))); + for content_type in ["application/javascript", "text/html"] { + let client = Arc::new(StreamingHttpClient::new()); + let length = (MAX_REWRITE_BODY_SIZE + 1).to_string(); + client.stub.push_response_with_headers( + 200, + vec![b' '; MAX_REWRITE_BODY_SIZE as usize + 1], + vec![ + ("content-type", content_type), + ("content-length", &length), + ("cache-control", "no-store"), + ], + ); + let services = build_services_with_http_client(client.clone()); + + let response = integration + .handle( + &settings, + &services, + make_req( + Method::GET, + "https://publisher.example.com/integrations/sourcepoint/cdn/asset", + ), + ) + .await + .expect("should pass through a declared oversized response"); + + assert!( + matches!(response.body(), EdgeBody::Stream(_)), + "should retain the original stream" + ); + assert_eq!( + client.reads.load(Ordering::Relaxed), + 0, + "should not poll a declared oversized body" + ); + assert_eq!( + get_header_str(&response, header::CONTENT_LENGTH), + Some(length.as_str()), + "should preserve the pass-through length" + ); + assert_eq!( + get_header_str(&response, header::CACHE_CONTROL), + Some("no-store"), + "should preserve upstream cache policy" + ); + } + }); + } + + #[test] + fn handle_keeps_ineligible_responses_streaming() { + futures::executor::block_on(async { + let settings = create_test_settings(); + for (content_type, method, status, rewrite_sdk) in [ + ("application/json", Method::GET, 200, true), + ("text/css", Method::GET, 200, true), + ("image/png", Method::GET, 200, true), + ("application/javascript", Method::GET, 200, false), + ("text/html", Method::GET, 200, false), + ("application/javascript", Method::HEAD, 200, true), + ("text/html", Method::POST, 200, true), + ("application/javascript", Method::GET, 206, true), + ("text/html", Method::GET, 404, true), + ] { + let mut cfg = config(true); + cfg.rewrite_sdk = rewrite_sdk; + let integration = SourcepointIntegration::new(Arc::new(cfg)); + let client = Arc::new(StreamingHttpClient::new()); + client.stub.push_response_with_headers( + status, + b"unchanged".to_vec(), + vec![ + ("content-type", content_type), + ("content-encoding", "gzip"), + ("cache-control", "no-store"), + ], + ); + let services = build_services_with_http_client(client.clone()); + let expected_body: &[u8] = if method == Method::HEAD { + b"" + } else { + b"unchanged" + }; + let mut request = make_req( + method, + "https://publisher.example.com/integrations/sourcepoint/cdn/asset", + ); + set_req_header(&mut request, header::ACCEPT_ENCODING, "gzip, br"); + + let response = integration + .handle(&settings, &services, request) + .await + .expect("should pass through an ineligible response"); + + assert!( + matches!(response.body(), EdgeBody::Stream(_)), + "should leave ineligible bodies streaming" + ); + assert_eq!( + client.reads.load(Ordering::Relaxed), + 0, + "should not poll an ineligible body" + ); + assert_eq!( + get_header_str(&response, header::CONTENT_ENCODING), + Some("gzip"), + "should preserve pass-through encoding" + ); + assert_eq!( + get_header_str(&response, header::CACHE_CONTROL), + Some("no-store"), + "should preserve pass-through cache policy" + ); + assert_eq!( + response + .into_body() + .into_bytes_bounded(1024) + .await + .expect("should collect pass-through body") + .as_ref(), + expected_body, + "should preserve pass-through bytes or omit them for HEAD" + ); + assert!( + client.stub.recorded_request_headers()[0] + .iter() + .any(|(name, value)| name == "accept-encoding" && value == "gzip, br"), + "should forward the client's encoding for non-script paths" + ); + } + }); + } + + #[test] + fn handle_rewrites_on_buffered_adapters_with_or_without_content_length() { + futures::executor::block_on(async { + let settings = create_test_settings(); + let integration = SourcepointIntegration::new(Arc::new(config(true))); + for has_length in [false, true] { + let client = Arc::new(StubHttpClient::new()); + let input = format!(r#"var api="https://{SOURCEPOINT_CDN_HOST}/consent/tcfv2";"#); + let length = input.len().to_string(); + let mut headers = vec![ + ("content-type", "application/javascript"), + ("content-encoding", "identity"), + ("vary", "Accept-Encoding, Origin"), + ]; + if has_length { + headers.push(("content-length", &length)); + } + client.push_response_with_headers(200, input.into_bytes(), headers); + let services = build_services_with_http_client(client.clone()); + + let response = integration + .handle( + &settings, + &services, + make_req( + Method::GET, + "https://publisher.example.com/integrations/sourcepoint/cdn/wrapper.js", + ), + ) + .await + .expect("should rewrite a buffered response"); + + assert_eq!( + client.recorded_stream_response_flags(), + vec![false], + "should respect adapters without streaming support" + ); + assert!( + response.headers().get(header::CONTENT_LENGTH).is_none(), + "should not forward a stale upstream length" + ); + assert!( + response.headers().get(header::CONTENT_ENCODING).is_none(), + "should remove upstream encoding after rewriting" + ); + assert_eq!( + get_header_str(&response, header::VARY), + Some("Origin"), + "should remove only Accept-Encoding from Vary" + ); + assert_eq!( + get_header_str(&response, header::CACHE_CONTROL), + Some("public, max-age=3600"), + "should retain the static JavaScript cache policy" + ); + assert_eq!( + get_header_str(&response, header::CONTENT_TYPE), + Some("application/javascript; charset=utf-8"), + "should identify rewritten JavaScript" + ); + assert_eq!( + take_body_bytes(response), + br#"var api="/integrations/sourcepoint/cdn/consent/tcfv2";"#, + "should rewrite with either header state" + ); + } + }); + } + + #[test] + fn handle_site_data_requests_identity_and_preserves_dynamic_cache_policy() { + futures::executor::block_on(async { + let settings = create_test_settings(); + let integration = SourcepointIntegration::new(Arc::new(config(true))); + for (upstream_cache, forwarded_cookies, sets_cookie, expected_cache) in [ + (Some("no-store"), false, false, "no-store"), + ( + Some("private, max-age=60"), + true, + false, + "private, max-age=60", + ), + (None, true, false, "private, max-age=0"), + (None, false, false, "public, max-age=3600"), + ( + Some("public, max-age=3600"), + false, + true, + "private, no-store", + ), + ] { + let client = Arc::new(StreamingHttpClient::new()); + let input = format!(r#"var api="https://{SOURCEPOINT_CDN_HOST}/consent/tcfv2";"#); + let mut headers = vec![("content-type", "application/javascript")]; + if let Some(cache) = upstream_cache { + headers.push(("cache-control", cache)); + } + if sets_cookie { + headers.push(("set-cookie", "consentUUID=example; Path=/")); + } + client + .stub + .push_response_with_headers(200, input.into_bytes(), headers); + let services = build_services_with_http_client(client.clone()); + let mut request = make_req( + Method::GET, + "https://publisher.example.com/integrations/sourcepoint/cdn/mms/v2/get_site_data?account_id=123", + ); + set_req_header(&mut request, header::ACCEPT_ENCODING, "gzip, br"); + if forwarded_cookies { + set_req_header(&mut request, header::COOKIE, "consentUUID=example"); + } + + let response = integration + .handle(&settings, &services, request) + .await + .expect("should rewrite dynamic site data"); + + assert!( + client.stub.recorded_request_headers()[0] + .iter() + .any(|(name, value)| name == "accept-encoding" && value == "identity"), + "should request uncompressed site data despite its extensionless path" + ); + assert_eq!( + get_header_str(&response, header::CACHE_CONTROL), + Some(expected_cache), + "should use the dynamic endpoint's cache policy" + ); + assert_eq!( + take_body_bytes(response), + br#"var api="/integrations/sourcepoint/cdn/consent/tcfv2";"#, + "should rewrite unknown-length site data" + ); + } + }); + } + + #[test] + fn handle_preserves_invalid_utf8_bytes_and_headers() { + futures::executor::block_on(async { + let settings = create_test_settings(); + let integration = SourcepointIntegration::new(Arc::new(config(true))); + let client = Arc::new(StreamingHttpClient::new()); + let bytes = vec![0x1f, 0x8b, 0xff]; + client.stub.push_response_with_headers( + 200, + bytes.clone(), + vec![ + ("content-type", "application/javascript"), + ("content-encoding", "gzip"), + ("cache-control", "no-store"), + ], + ); + let services = build_services_with_http_client(client); + + let response = integration + .handle( + &settings, + &services, + make_req( + Method::GET, + "https://publisher.example.com/integrations/sourcepoint/cdn/wrapper.js", + ), + ) + .await + .expect("should retain non-UTF-8 content unchanged"); + + assert_eq!( + get_header_str(&response, header::CONTENT_ENCODING), + Some("gzip"), + "should preserve encoding when no rewrite occurs" + ); + assert_eq!( + get_header_str(&response, header::CACHE_CONTROL), + Some("no-store"), + "should preserve cache policy when no rewrite occurs" + ); + assert_eq!( + take_body_bytes(response), + bytes, + "should preserve invalid UTF-8 bytes" + ); + }); + } fn config(enabled: bool) -> SourcepointConfig { SourcepointConfig { @@ -1444,9 +1996,12 @@ mod tests { assert!(SourcepointIntegration::is_likely_javascript_path( "/module/sourcepoint.mjs" )); - assert!(!SourcepointIntegration::is_likely_javascript_path( + assert!(SourcepointIntegration::is_likely_javascript_path( "/mms/v2/get_site_data" )); + assert!(!SourcepointIntegration::is_likely_javascript_path( + "/mms/v2/get_site_data/other" + )); assert!(!SourcepointIntegration::is_likely_javascript_path( "/consent/tcfv2" )); @@ -1950,7 +2505,12 @@ mod tests { set_header(&mut response, header::CACHE_CONTROL, "no-store"); *response.body_mut() = EdgeBody::from(b"payload".to_vec()); - integration.rewrite_javascript_response(&mut response, "rewritten".to_string()); + integration.rewrite_javascript_response( + &mut response, + "rewritten".to_string(), + "/wrapper.js", + false, + ); assert_eq!(response.status(), StatusCode::OK); assert_eq!( @@ -1989,7 +2549,12 @@ mod tests { set_header(&mut response, header::CACHE_CONTROL, "public, max-age=3600"); *response.body_mut() = EdgeBody::from(b"payload".to_vec()); - integration.rewrite_javascript_response(&mut response, "rewritten".to_string()); + integration.rewrite_javascript_response( + &mut response, + "rewritten".to_string(), + "/wrapper.js", + false, + ); assert_eq!( get_header_str(&response, header::CACHE_CONTROL), @@ -2009,7 +2574,12 @@ mod tests { set_header(&mut response, header::VARY, "Accept-Encoding"); *response.body_mut() = EdgeBody::from(b"payload".to_vec()); - integration.rewrite_javascript_response(&mut response, "rewritten".to_string()); + integration.rewrite_javascript_response( + &mut response, + "rewritten".to_string(), + "/wrapper.js", + false, + ); assert!( response.headers().get(header::VARY).is_none(), 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..6d57a429c --- /dev/null +++ b/crates/trusted-server-core/src/platform/timed_kv.rs @@ -0,0 +1,253 @@ +//! Latency-only timing decorator for KV store handles. +//! +//! [`TimedKvStore`] wraps an inner store plus a [`RequestTimings`] handle and +//! records [`Phase::EcKv`] around every call. It implements both +//! [`PlatformKvStore`] (for consent-store access obtained through +//! [`RuntimeServices`](super::RuntimeServices)) and [`EcKvStore`] (for +//! [`KvIdentityGraph`](crate::ec::kv::KvIdentityGraph) construction sites), +//! because no single existing abstraction covers the whole `ts-kv` taxonomy: +//! EC graph operations go through [`EcKvStore`] while consent persistence +//! uses [`PlatformKvStore`] directly. +//! +//! The decorator measures store-call latency only: it never reads, parses, +//! or logs any value passing through it. + +use std::sync::Arc; +use std::time::Duration; + +use async_trait::async_trait; +use bytes::Bytes; +use edgezero_core::key_value_store::{KvError, KvPage, KvStore as PlatformKvStore}; +use error_stack::Report; + +use crate::ec::kv_backend::{EcKvLookup, EcKvStore, EcKvWrite, EcKvWriteOutcome}; +use crate::error::TrustedServerError; +use crate::request_timing::{Phase, RequestTimings}; + +/// Wraps `inner` plus a [`RequestTimings`] handle, recording [`Phase::EcKv`] +/// around every store call made through it. +pub struct TimedKvStore { + /// The wrapped store handle. + inner: S, + /// The request's phase-timing collector. + timings: RequestTimings, +} + +impl TimedKvStore { + /// Creates a decorator around `inner` that records into `timings`. + #[must_use] + pub fn new(inner: S, timings: RequestTimings) -> Self { + Self { inner, timings } + } +} + +#[async_trait(?Send)] +impl PlatformKvStore for TimedKvStore> { + async fn get_bytes(&self, key: &str) -> Result, KvError> { + let _span = self.timings.span(Phase::EcKv); + self.inner.get_bytes(key).await + } + + async fn put_bytes(&self, key: &str, value: Bytes) -> Result<(), KvError> { + let _span = self.timings.span(Phase::EcKv); + self.inner.put_bytes(key, value).await + } + + // Forwarded explicitly: the trait's default body falls back to + // `get_bytes`, which would silently downgrade a backend's cheap + // metadata-only existence probe (the Spin adapter has one) into a full + // value transfer just because the store was decorated. + async fn exists(&self, key: &str) -> Result { + let _span = self.timings.span(Phase::EcKv); + self.inner.exists(key).await + } + + async fn put_bytes_with_ttl( + &self, + key: &str, + value: Bytes, + ttl: Duration, + ) -> Result<(), KvError> { + let _span = self.timings.span(Phase::EcKv); + self.inner.put_bytes_with_ttl(key, value, ttl).await + } + + async fn delete(&self, key: &str) -> Result<(), KvError> { + let _span = self.timings.span(Phase::EcKv); + self.inner.delete(key).await + } + + async fn list_keys_page( + &self, + prefix: &str, + cursor: Option<&str>, + limit: usize, + ) -> Result { + let _span = self.timings.span(Phase::EcKv); + self.inner.list_keys_page(prefix, cursor, limit).await + } +} + +impl EcKvStore for TimedKvStore { + fn store_name(&self) -> &str { + self.inner.store_name() + } + + fn lookup(&self, key: &str) -> Result, Report> { + let _span = self.timings.span(Phase::EcKv); + self.inner.lookup(key) + } + + fn insert( + &self, + key: &str, + write: EcKvWrite<'_>, + ) -> Result> { + let _span = self.timings.span(Phase::EcKv); + self.inner.insert(key, write) + } + + fn key_exists(&self, key: &str) -> Result> { + let _span = self.timings.span(Phase::EcKv); + self.inner.key_exists(key) + } + + 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 delete(&self, key: &str) -> Result<(), Report> { + let _span = self.timings.span(Phase::EcKv); + self.inner.delete(key) + } +} + +#[cfg(test)] +mod tests { + use std::time::Duration as StdDuration; + + use super::*; + use crate::ec::kv_backend::test_support::InMemoryEcKv; + + #[test] + fn ec_kv_store_operations_accumulate_into_ec_kv_phase() { + let timings = RequestTimings::new(); + let store = TimedKvStore::new(InMemoryEcKv::new("test-store"), timings.clone()); + + store + .insert( + "key-a", + EcKvWrite { + body: "{}", + metadata: "{}", + ttl: StdDuration::from_secs(60), + mode: crate::ec::kv_backend::EcKvWriteMode::Add, + }, + ) + .expect("should insert into the in-memory store"); + store.lookup("key-a").expect("should read back the entry"); + + timings.mark_headers_ready(); + assert!( + timings.snapshot().kv_ms.is_some(), + "should record Phase::EcKv across both store calls" + ); + } + + #[test] + fn exists_delegates_to_the_inner_store_not_get_bytes() { + // A stub whose `exists` answer contradicts its `get_bytes` answer: + // if the decorator fell back to the trait's get-and-discard default + // body, this would return `false`. + struct ExistsOnlyStore; + + #[async_trait::async_trait(?Send)] + impl PlatformKvStore for ExistsOnlyStore { + async fn get_bytes(&self, _key: &str) -> Result, KvError> { + Ok(None) + } + async fn put_bytes(&self, _key: &str, _value: Bytes) -> Result<(), KvError> { + Ok(()) + } + async fn put_bytes_with_ttl( + &self, + _key: &str, + _value: Bytes, + _ttl: StdDuration, + ) -> Result<(), KvError> { + Ok(()) + } + async fn delete(&self, _key: &str) -> Result<(), KvError> { + Ok(()) + } + async fn list_keys_page( + &self, + _prefix: &str, + _cursor: Option<&str>, + _limit: usize, + ) -> Result { + Ok(KvPage { + keys: Vec::new(), + cursor: None, + }) + } + async fn exists(&self, _key: &str) -> Result { + Ok(true) + } + } + + let timings = RequestTimings::new(); + let inner: Arc = Arc::new(ExistsOnlyStore); + let store = TimedKvStore::new(inner, timings.clone()); + + let exists = futures::executor::block_on(store.exists("key")) + .expect("should forward the existence probe"); + assert!( + exists, + "should delegate to the inner exists, not the get_bytes default body" + ); + timings.mark_headers_ready(); + assert!( + timings.snapshot().kv_ms.is_some(), + "should time the existence probe like any other store operation" + ); + } + + #[test] + fn store_name_is_not_timed() { + let timings = RequestTimings::new(); + let store = TimedKvStore::new(InMemoryEcKv::new("test-store"), timings.clone()); + + assert_eq!(store.store_name(), "test-store"); + timings.mark_headers_ready(); + assert!( + timings.snapshot().kv_ms.is_none(), + "store_name is a metadata accessor, not a store operation" + ); + } + + #[test] + fn platform_kv_store_operations_accumulate_into_ec_kv_phase() { + let timings = RequestTimings::new(); + let inner: Arc = Arc::new(crate::platform::UnavailableKvStore); + let store = TimedKvStore::new(inner, timings.clone()); + + // UnavailableKvStore errors on every call; the decorator still times + // the attempt regardless of outcome. + futures::executor::block_on(async { + let _ = store.get_bytes("key").await; + let _ = store.put_bytes("key", Bytes::from_static(b"value")).await; + }); + + timings.mark_headers_ready(); + assert!( + timings.snapshot().kv_ms.is_some(), + "should record Phase::EcKv even when the inner store errors" + ); + } +} diff --git a/crates/trusted-server-core/src/publisher.rs b/crates/trusted-server-core/src/publisher.rs index 61bc7efe5..740a5dc3c 100644 --- a/crates/trusted-server-core/src/publisher.rs +++ b/crates/trusted-server-core/src/publisher.rs @@ -75,6 +75,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, @@ -95,21 +96,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", @@ -132,6 +156,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)] @@ -1726,6 +1751,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 @@ -1969,6 +2000,8 @@ pub async fn buffer_publisher_response_async( ¶ms.request_scheme, ¶ms.request_host, ), + timings: params.timings.clone(), + placement: AuctionWaitPlacement::PreHeader, }, ) .await; @@ -2130,6 +2163,7 @@ fn build_template_assembly_params( request_scheme: &str, price_granularity: PriceGranularity, ad_bids_state: AdBidsState, + timings: RequestTimings, ) -> OwnedProcessResponseParams { OwnedProcessResponseParams { csp_nonce_observed: None, @@ -2152,6 +2186,7 @@ fn build_template_assembly_params( price_granularity, gpt_diagnostics: None, suppress_datadome_client_side_tag: false, + timings, } } @@ -2494,6 +2529,8 @@ pub async fn publisher_response_into_streaming_response( ¶ms.request_scheme, ¶ms.request_host, ), + timings: params.timings.clone(), + placement: AuctionWaitPlacement::InStream, }, ) .await; @@ -2612,6 +2649,7 @@ pub async fn publisher_response_into_streaming_response( &orchestrator, &services, &settings, + AuctionWaitPlacement::InStream, ) .await; // Collection reached a terminal result; disarm only now @@ -2637,6 +2675,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( @@ -2981,6 +3021,7 @@ pub async fn stream_publisher_body_async( orchestrator, services, settings, + AuctionWaitPlacement::PreHeader, ) .await; if body.is_stream() { @@ -3055,6 +3096,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, }, }, ) @@ -3240,6 +3283,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); @@ -5960,6 +6172,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!( "