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/crates/trusted-server-adapter-cloudflare/wrangler.integration.generated.toml b/crates/trusted-server-adapter-cloudflare/wrangler.integration.generated.toml deleted file mode 100644 index 263403193..000000000 --- a/crates/trusted-server-adapter-cloudflare/wrangler.integration.generated.toml +++ /dev/null @@ -1,16 +0,0 @@ -name = "trusted-server" -main = "build/index.js" -compatibility_date = "2024-09-23" -# Keep in sync with wrangler.toml. `cache_option_enabled` is required for the -# outbound `CacheMode::NoStore` cache bypass under this compatibility date. -compatibility_flags = ["nodejs_compat", "cache_option_enabled"] -# No [build] section — bundle is pre-built in CI; wrangler dev must not rebuild. - -[[kv_namespaces]] -binding = "TRUSTED_SERVER_KV" -id = "ci-local-kv" - -[vars] -# Placeholder replaced by the integration test harness with a JSON object that -# contains the runtime Trusted Server app-config blob envelope. -TRUSTED_SERVER_CONFIG = '''{"app_config":"{\"data\":{\"auction\":{\"allowed_context_keys\":[],\"creative_store\":\"creative_store\",\"enabled\":false,\"mediator\":null,\"providers\":[],\"timeout_ms\":2000},\"cache\":{\"asset_rules\":[]},\"consent\":{\"check_expiration\":true,\"conflict_resolution\":{\"freshness_threshold_days\":30,\"mode\":\"restrictive\"},\"gdpr\":{\"applies_in\":[\"AT\",\"BE\",\"BG\",\"HR\",\"CY\",\"CZ\",\"DK\",\"EE\",\"FI\",\"FR\",\"DE\",\"GR\",\"HU\",\"IE\",\"IT\",\"LV\",\"LT\",\"LU\",\"MT\",\"NL\",\"PL\",\"PT\",\"RO\",\"SK\",\"SI\",\"ES\",\"SE\",\"IS\",\"LI\",\"NO\",\"GB\"]},\"max_consent_age_days\":395,\"mode\":\"interpreter\",\"us_privacy_defaults\":{\"gpc_implies_optout\":true,\"lspa_covered\":false,\"notice_given\":true},\"us_states\":{\"privacy_states\":[\"CA\",\"VA\",\"CO\",\"CT\",\"UT\",\"MT\",\"OR\",\"TX\",\"FL\",\"DE\",\"IA\",\"NE\",\"NH\",\"NJ\",\"TN\",\"MN\",\"MD\",\"IN\",\"KY\",\"RI\"]}},\"creative_opportunities\":null,\"debug\":{\"auction_html_comment\":false,\"inject_adm_for_testing\":false,\"ja4_endpoint_enabled\":false},\"ec\":{\"cluster_recheck_secs\":3600,\"cluster_trust_threshold\":10,\"ec_store\":\"ec_identity_store\",\"partners\":[{\"api_token\":\"integration-test-token-alpha-32-bytes-ok\",\"batch_rate_limit\":60,\"bidstream_enabled\":true,\"name\":\"Integration Test Partner\",\"openrtb_atype\":3,\"pull_sync_allowed_domains\":[],\"pull_sync_enabled\":false,\"pull_sync_rate_limit\":10,\"pull_sync_ttl_sec\":86400,\"pull_sync_url\":null,\"source_domain\":\"inttest.example.com\",\"ts_pull_token\":null},{\"api_token\":\"integration-test-token-bravo-32-bytes-ok\",\"batch_rate_limit\":60,\"bidstream_enabled\":true,\"name\":\"Integration Test Partner 2\",\"openrtb_atype\":3,\"pull_sync_allowed_domains\":[],\"pull_sync_enabled\":false,\"pull_sync_rate_limit\":10,\"pull_sync_ttl_sec\":86400,\"pull_sync_url\":null,\"source_domain\":\"inttest2.example.com\",\"ts_pull_token\":null}],\"passphrase\":\"integration-test-ec-secret-padded-32\",\"pull_sync_concurrency\":3},\"handlers\":[{\"password\":\"integration-admin-password-32-bytes-ok\",\"path\":\"^/_ts/admin\",\"username\":\"admin\"}],\"image_optimizer\":{\"profile_sets\":{}},\"integrations\":{\"adserver_mock\":{\"context_query_params\":{\"example_segments\":\"segments\"},\"enabled\":false,\"endpoint\":\"https://adserver.example.com/mediate\",\"timeout_ms\":1000},\"aps\":{\"account_id\":\"example-aps-account-id\",\"allow_script_creatives\":false,\"enabled\":true,\"endpoint\":\"https://aps.example.com/e/pb/bid\",\"timeout_ms\":1000},\"datadome\":{\"api_origin\":\"https://api.example.com\",\"cache_ttl_seconds\":3600,\"enabled\":false,\"rewrite_sdk\":true,\"sdk_origin\":\"https://sdk.example.com\"},\"didomi\":{\"api_origin\":\"https://api.example.com\",\"enabled\":false,\"sdk_origin\":\"https://sdk.example.com\"},\"google_tag_manager\":{\"container_id\":\"GTM-EXAMPLE\",\"enabled\":false,\"upstream_url\":\"https://tags.example.com\"},\"gpt\":{\"cache_ttl_seconds\":3600,\"enabled\":false,\"gam_attribution_enabled\":false,\"rewrite_script\":true,\"script_url\":\"https://ads.example.com/gpt.js\"},\"gpt_diagnostics\":{\"enabled\":true},\"lockr\":{\"api_endpoint\":\"https://identity.example.com\",\"app_id\":\"\",\"cache_ttl_seconds\":3600,\"enabled\":false,\"rewrite_sdk\":true,\"sdk_url\":\"https://identity.example.com/trusted-server.js\"},\"nextjs\":{\"enabled\":false,\"max_combined_payload_bytes\":10485760,\"rewrite_attributes\":[\"href\",\"link\",\"siteBaseUrl\",\"siteProductionDomain\",\"url\"]},\"permutive\":{\"api_endpoint\":\"https://api.example.com\",\"enabled\":false,\"organization_id\":\"\",\"project_id\":\"\",\"secure_signals_endpoint\":\"https://secure-signals.example.com\",\"workspace_id\":\"\"},\"prebid\":{\"bidders\":[],\"client_side_bidders\":[],\"debug\":false,\"enabled\":false,\"server_url\":\"https://prebid.example.com/openrtb2/auction\",\"timeout_ms\":1000},\"sourcepoint\":{\"cache_ttl_seconds\":3600,\"cdn_origin\":\"https://cdn.example.com\",\"enabled\":false,\"rewrite_sdk\":true},\"testlight\":{\"enabled\":false,\"endpoint\":\"https://testlight.example.com/openrtb2/auction\",\"rewrite_scripts\":true,\"timeout_ms\":1200}},\"proxy\":{\"allowed_domains\":[],\"asset_routes\":[],\"certificate_check\":false},\"publisher\":{\"cookie_domain\":\"localhost\",\"domain\":\"localhost\",\"max_buffered_body_bytes\":16777216,\"origin_host_header_override\":null,\"origin_url\":\"http://127.0.0.1:8888\",\"proxy_secret\":\"integration-test-proxy-secret\"},\"request_signing\":{\"config_store_id\":\"app_config\",\"enabled\":false,\"secret_store_id\":\"secrets\"},\"response_headers\":{},\"rewrite\":{\"exclude_domains\":[]},\"tester_cookie\":{\"enabled\":false},\"tinybird\":{\"access_dataset\":\"access_logs_raw\",\"access_enabled\":false,\"access_sample_rate\":0.0,\"access_token_secret\":\"tinybird_access_append_token\",\"api_host\":\"\",\"auction_dataset\":\"auction_events_raw\",\"auction_enabled\":true,\"auction_token_secret\":\"tinybird_auction_append_token\",\"enabled\":false,\"max_body_bytes\":1048576,\"secret_store\":\"ts_secrets\"}},\"generated_at\":\"2026-06-23T00:00:00Z\",\"sha256\":\"895f7fad0ce924476d1c04c68b0bf95f463d1fb631a4f639dcc7cf0c510383b4\",\"version\":1}"}''' diff --git a/crates/trusted-server-core/src/access_telemetry.rs b/crates/trusted-server-core/src/access_telemetry.rs index e468b109c..3cf9c693f 100644 --- a/crates/trusted-server-core/src/access_telemetry.rs +++ b/crates/trusted-server-core/src/access_telemetry.rs @@ -220,11 +220,13 @@ pub struct AccessTelemetrySnapshot { /// /// Column names match spec section 9 exactly. Phase columns come from /// `timings` and serialize as JSON `null` for phases that were never -/// recorded; every dimension column comes from `snapshot` and is a -/// non-nullable string (callers are expected to substitute an `unknown` -/// sentinel rather than leave a dimension empty). There is no `event_date` -/// column: the datasource's sorting key derives the date via -/// `toDate(event_ts)`. +/// recorded, as do the auction timeline columns (including `auction_id`, +/// whose datasource column is `Nullable(UUID)` so it joins natively against +/// `auction_events_raw.auction_id`). Every dimension column comes from +/// `snapshot` and is a non-nullable string (callers are expected to +/// substitute an `unknown` sentinel rather than leave a dimension empty). +/// There is no `event_date` column: the datasource's sorting key derives the +/// date via `toDate(event_ts)`. #[must_use] pub fn access_event_row( snapshot: &AccessTelemetrySnapshot, @@ -260,6 +262,10 @@ pub fn access_event_row( "stream_ms": timings.stream_ms, "request_elapsed_ms": timings.request_elapsed_ms, "resp_bytes": timings.resp_bytes, + "auction_dispatched_ms": timings.auction_dispatched_ms, + "auction_resolved_ms": timings.auction_resolved_ms, + "auction_committed_ms": timings.auction_committed_ms, + "auction_id": timings.auction_id.map(|id| id.to_string()), "template_cache_state": snapshot.template_cache_state, "country": snapshot.country, "ts_version": snapshot.ts_version, @@ -427,6 +433,10 @@ mod tests { "stream_ms", "request_elapsed_ms", "resp_bytes", + "auction_dispatched_ms", + "auction_resolved_ms", + "auction_committed_ms", + "auction_id", ] { assert!( parsed[field].is_null(), @@ -452,6 +462,10 @@ mod tests { ); } assert_eq!(parsed["auction_wait_placement"], "none"); + assert!( + row.contains("\"auction_id\":null"), + "auction_id should serialize as an explicit null key, not be omitted: {row}" + ); } #[test] @@ -470,6 +484,10 @@ mod tests { stream_ms: Some(8), auction_wait_placement: Some(AuctionWaitPlacement::InStream), resp_bytes: Some(1024), + auction_dispatched_ms: Some(9), + auction_resolved_ms: Some(10), + auction_committed_ms: Some(11), + auction_id: Some(uuid::uuid!("33333333-3333-3333-3333-333333333333")), }; let row = access_event_row(&snapshot, &timings, 1_700_000_000_000); let parsed: serde_json::Value = @@ -479,6 +497,10 @@ mod tests { assert_eq!(parsed["stream_ms"], 8); assert_eq!(parsed["resp_bytes"], 1024); assert_eq!(parsed["auction_wait_placement"], "in_stream"); + assert_eq!(parsed["auction_dispatched_ms"], 9); + assert_eq!(parsed["auction_resolved_ms"], 10); + assert_eq!(parsed["auction_committed_ms"], 11); + assert_eq!(parsed["auction_id"], "33333333-3333-3333-3333-333333333333"); } #[test] diff --git a/crates/trusted-server-core/src/auction/endpoints.rs b/crates/trusted-server-core/src/auction/endpoints.rs index 35c2cb3a2..fe42fc6b7 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() @@ -318,10 +329,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( @@ -366,6 +384,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/publisher.rs b/crates/trusted-server-core/src/publisher.rs index c0dd3dc15..e367552e8 100644 --- a/crates/trusted-server-core/src/publisher.rs +++ b/crates/trusted-server-core/src/publisher.rs @@ -4000,6 +4000,8 @@ async fn collect_non_html_auction( params .timings .record_auction_wait(placement, wait_started.elapsed()); + // T0-anchored timeline mark (spec section 18): final bid or timeout. + params.timings.mark_auction_resolved(); let delivered_winner_slots = write_bids_to_state( &result.winning_bids, params.price_granularity, @@ -4009,6 +4011,9 @@ async fn collect_non_html_auction( settings.debug.inject_adm_for_testing, auction_id.as_deref(), ); + // T0-anchored timeline mark (spec section 18): winning bids are in page + // state, available to the response pipeline. + params.timings.mark_auction_committed(); if let (Some(observation), Some(auction_request)) = (telemetry.observation, telemetry.auction_request.as_ref()) { @@ -4059,6 +4064,8 @@ async fn collect_stream_auction( .collect_dispatched_auction(dispatched, services, &collect_ctx) .await; timings.record_auction_wait(*placement, wait_started.elapsed()); + // T0-anchored timeline mark (spec section 18): final bid or timeout. + timings.mark_auction_resolved(); log::info!( "body_close_hold_loop: collect complete - {} winning bid(s)", result.winning_bids.len() @@ -4072,6 +4079,9 @@ async fn collect_stream_auction( settings.debug.inject_adm_for_testing, auction_id.as_deref(), ); + // T0-anchored timeline mark (spec section 18): winning bids are in page + // state, available to the response pipeline. + timings.mark_auction_committed(); if let (Some(observation), Some(auction_request)) = (telemetry.observation, telemetry.auction_request.as_ref()) { @@ -4537,6 +4547,12 @@ pub async fn handle_publisher_request( matched_slots.len(), ec_context, ); + // T0-anchored timeline (spec section 18): stamp the join key here + // rather than on dispatch, because every branch below emits an + // `auction_events_raw` row under this id — completed, dispatch + // failed, and skipped alike. Stamping it on dispatch would leave the + // failed and skipped rows unjoinable. + timings.set_auction_id(observation.auction_id); if should_run_auction { let slots_ctx = MatchedSlotsContext { @@ -4580,6 +4596,11 @@ pub async fn handle_publisher_request( .await { DispatchAuctionOutcome::Dispatched(dispatched) => { + // Bid requests have left the edge. A skipped auction or a + // failed dispatch never reaches this arm, so a null + // dispatch offset next to a non-null `auction_id` reads as + // "attempted, nothing sent". + timings.mark_auction_dispatched(); auction_request_for_telemetry = Some(auction_request); auction_observation = Some(observation); Some(dispatched) @@ -6519,6 +6540,14 @@ pub async fn handle_page_bids( ec_context: &mut EcContext, req: Request, ) -> Result, Report> { + // Same defaulted-handle rule as `handle_publisher_request`: a request + // without the extension records into a collector nothing reads. + let timings = req + .extensions() + .get::() + .cloned() + .unwrap_or_default(); + // CSRF-style gate: refuse cross-site invocations before any other work — // including the not-configured 404 below, which would otherwise tell a // cross-site caller whether this deployment has creative opportunities. @@ -6678,6 +6707,11 @@ pub async fn handle_page_bids( matched_slots.len(), ec_context, ); + // Same T0-anchored timeline as the navigation path (spec section 18). + // This route runs the auction through `run_auction` rather than the + // dispatch/collect split, so dispatch and resolve bracket that one + // call instead of the origin fetch. + timings.set_auction_id(observation.auction_id); if ad_stack_enabled && !is_bot && !is_prefetch { let slots_ctx = MatchedSlotsContext { matched_slots: &matched_slots, @@ -6732,12 +6766,14 @@ pub async fn handle_page_bids( provider_responses: None, services, }; + timings.mark_auction_dispatched(); match auction .orchestrator .run_auction(&auction_request, &auction_context) .await { Ok(result) => { + timings.mark_auction_resolved(); let winning_bids = result.winning_bids.clone(); let auction_id = diagnostics_auction_id(settings); let bid_map = build_bid_map_with_auction_id( @@ -6748,6 +6784,8 @@ pub async fn handle_page_bids( settings.debug.inject_adm_for_testing, auction_id.as_deref(), ); + // Targeting is available to the response pipeline. + timings.mark_auction_committed(); let delivered_winner_slots = bid_map.keys().cloned().collect(); emit_auction_events_best_effort_lazy(services, || { build_auction_events( @@ -6763,6 +6801,7 @@ pub async fn handle_page_bids( (winning_bids, Some(bid_map)) } Err(e) => { + timings.mark_auction_resolved(); log::warn!("page-bids auction failed: {e:?}"); let elapsed_ms = observation.elapsed_ms(); emit_auction_events_best_effort_lazy(services, || { @@ -18327,6 +18366,17 @@ mod tests { snapshot.auction_wait_ms.is_some(), "should record an auction wait duration" ); + // The T0 marks are recorded at this same collect site, so a collect + // path that stops calling them fails here rather than silently + // emitting null columns. + assert!( + snapshot.auction_resolved_ms.is_some(), + "should mark the auction resolved at the streaming collect site" + ); + assert!( + snapshot.auction_committed_ms.is_some(), + "should mark the auction committed at the streaming collect site" + ); } #[test] @@ -18400,6 +18450,16 @@ mod tests { snapshot.auction_wait_ms.is_some(), "should record an auction wait duration" ); + // Same guard as the streaming test: both collect sites must mark, or + // one body mode quietly reports null offsets. + assert!( + snapshot.auction_resolved_ms.is_some(), + "should mark the auction resolved at the buffered collect site" + ); + assert!( + snapshot.auction_committed_ms.is_some(), + "should mark the auction committed at the buffered collect site" + ); } #[test] diff --git a/crates/trusted-server-core/src/request_timing.rs b/crates/trusted-server-core/src/request_timing.rs index 3b26c3ca2..899674d7d 100644 --- a/crates/trusted-server-core/src/request_timing.rs +++ b/crates/trusted-server-core/src/request_timing.rs @@ -10,6 +10,7 @@ use std::sync::{Arc, Mutex, TryLockError}; use std::time::Duration; use http::{HeaderName, HeaderValue, Response}; +use uuid::Uuid; // `std::time::Instant::now()` panics on `wasm32-unknown-unknown` (the // Cloudflare adapter's target); `web_time` re-exports std's `Instant` on // every other target. @@ -113,6 +114,22 @@ struct Inner { /// Response body size in bytes, set via /// [`RequestTimings::set_resp_bytes`]. resp_bytes: Option, + /// Elapsed time at the first + /// [`RequestTimings::mark_auction_dispatched`] call. + auction_dispatched: Option, + /// Elapsed time at the first + /// [`RequestTimings::mark_auction_resolved`] call. + auction_resolved: Option, + /// Elapsed time at the first + /// [`RequestTimings::mark_auction_committed`] call. + auction_committed: Option, + /// Telemetry auction UUID recorded by the first + /// [`RequestTimings::set_auction_id`] call; joins the access row to the + /// per-bidder auction dataset. Set when the auction observation is + /// built, so it is present even for an auction that was skipped or + /// failed to dispatch, matching the row those outcomes emit to + /// `auction_events_raw`. + auction_id: Option, } /// Per-request phase timing collector. @@ -135,6 +152,10 @@ impl RequestTimings { request_elapsed: None, auction_wait_placement: None, resp_bytes: None, + auction_dispatched: None, + auction_resolved: None, + auction_committed: None, + auction_id: None, }))) } @@ -231,6 +252,101 @@ impl RequestTimings { } } + /// Records the telemetry auction id, the first time this is called. + /// + /// Called where the auction observation is built, which happens on every + /// auction-eligible request regardless of outcome, so the access row can + /// be joined to the `auction_events_raw` row even when the auction was + /// skipped or failed to dispatch. Kept separate from + /// [`RequestTimings::mark_auction_dispatched`] so a dropped dispatch + /// sample cannot also lose the join key. Subsequent calls are no-ops + /// (first call wins). Drops the sample silently on lock contention; a + /// poisoned lock is recovered. + pub fn set_auction_id(&self, auction_id: Uuid) { + let mut inner = match self.0.try_lock() { + Ok(guard) => guard, + // Poisoning is recoverable here: the guarded data are plain + // counters with no invariant a panic can break, so recording + // keeps working for the rest of the request instead of going + // silently dark. Contention still drops the one sample. + Err(TryLockError::Poisoned(poisoned)) => poisoned.into_inner(), + Err(TryLockError::WouldBlock) => return, + }; + if inner.auction_id.is_none() { + inner.auction_id = Some(auction_id); + } + } + + /// Stamps the elapsed time since `t0` as the auction dispatch offset, + /// the first time this is called. + /// + /// Called where the bid requests leave the edge. A skipped auction and a + /// failed dispatch never stamp it, so a null dispatch offset alongside a + /// non-null `auction_id` means an auction was attempted but no bid + /// request went out. Subsequent calls are no-ops (first call wins). + /// Drops the sample silently on lock contention; a poisoned lock is + /// recovered. + pub fn mark_auction_dispatched(&self) { + let mut inner = match self.0.try_lock() { + Ok(guard) => guard, + // Poisoning is recoverable here: the guarded data are plain + // counters with no invariant a panic can break, so recording + // keeps working for the rest of the request instead of going + // silently dark. Contention still drops the one sample. + Err(TryLockError::Poisoned(poisoned)) => poisoned.into_inner(), + Err(TryLockError::WouldBlock) => return, + }; + if inner.auction_dispatched.is_none() { + inner.auction_dispatched = Some(inner.t0.elapsed()); + } + } + + /// Stamps the elapsed time since `t0` as the auction resolve offset (the + /// final bid returned or the auction timed out), the first time this is + /// called. + /// + /// Stays `None` when a dispatched auction is abandoned before collection + /// (origin error, bodiless response, reader disconnect), so a non-null + /// dispatch offset with a null resolve offset is the "dispatched, never + /// collected" case rather than "no auction ran". Subsequent calls are + /// no-ops (first call wins). Drops the sample silently on lock + /// contention; a poisoned lock is recovered. + pub fn mark_auction_resolved(&self) { + let mut inner = match self.0.try_lock() { + Ok(guard) => guard, + // Poisoning is recoverable here: the guarded data are plain + // counters with no invariant a panic can break, so recording + // keeps working for the rest of the request instead of going + // silently dark. Contention still drops the one sample. + Err(TryLockError::Poisoned(poisoned)) => poisoned.into_inner(), + Err(TryLockError::WouldBlock) => return, + }; + if inner.auction_resolved.is_none() { + inner.auction_resolved = Some(inner.t0.elapsed()); + } + } + + /// Stamps the elapsed time since `t0` as the auction commit offset + /// (winning bids available to the response pipeline), the first time + /// this is called. + /// + /// Subsequent calls are no-ops (first call wins). Drops the sample + /// silently on lock contention; a poisoned lock is recovered. + pub fn mark_auction_committed(&self) { + let mut inner = match self.0.try_lock() { + Ok(guard) => guard, + // Poisoning is recoverable here: the guarded data are plain + // counters with no invariant a panic can break, so recording + // keeps working for the rest of the request instead of going + // silently dark. Contention still drops the one sample. + Err(TryLockError::Poisoned(poisoned)) => poisoned.into_inner(), + Err(TryLockError::WouldBlock) => return, + }; + if inner.auction_committed.is_none() { + inner.auction_committed = Some(inner.t0.elapsed()); + } + } + /// Records the response body size in bytes. /// /// Drops the sample silently on lock contention; a poisoned lock is recovered. @@ -300,6 +416,10 @@ impl RequestTimings { stream_ms: duration_ms(inner.phases[Phase::Stream.index()]), auction_wait_placement: inner.auction_wait_placement, resp_bytes: inner.resp_bytes, + auction_dispatched_ms: duration_ms(inner.auction_dispatched), + auction_resolved_ms: duration_ms(inner.auction_resolved), + auction_committed_ms: duration_ms(inner.auction_committed), + auction_id: inner.auction_id, } } } @@ -422,6 +542,23 @@ pub struct TimingSnapshot { /// Response body size in bytes, set via /// [`RequestTimings::set_resp_bytes`]. pub resp_bytes: Option, + /// T0 offset at which the auction dispatched (bid requests left the + /// edge). `None` when no bid request went out, which covers both "no + /// auction was attempted" and "the auction was skipped or failed to + /// dispatch" — `auction_id` separates the two. + pub auction_dispatched_ms: Option, + /// T0 offset at which the auction resolved (final bid or timeout). + /// `None` when the milestone was never reached, including a dispatched + /// auction abandoned before collection. + pub auction_resolved_ms: Option, + /// T0 offset at which winning bids became available to the response + /// pipeline. `None` when the milestone was never reached. + pub auction_committed_ms: Option, + /// Telemetry auction UUID joining this row to the auction dataset. + /// `None` only when no auction was attempted at all; an attempted + /// auction carries the id whatever its outcome, matching the row it + /// emits to `auction_events_raw`. + pub auction_id: Option, } #[cfg(test)] @@ -475,6 +612,87 @@ mod tests { ); } + #[test] + fn auction_marks_are_first_call_wins_and_snapshot_maps_them() { + let timings = RequestTimings::new(); + timings.set_auction_id(uuid::uuid!("11111111-1111-1111-1111-111111111111")); + timings.mark_auction_dispatched(); + timings.mark_auction_resolved(); + timings.mark_auction_committed(); + let first = timings.snapshot(); + + // Sleep so a restamp would land on a different millisecond: without + // it both stamps fall in the same millisecond and an equality + // assertion would hold even under last-call-wins. + std::thread::sleep(Duration::from_millis(5)); + timings.set_auction_id(uuid::uuid!("22222222-2222-2222-2222-222222222222")); + timings.mark_auction_dispatched(); + timings.mark_auction_resolved(); + timings.mark_auction_committed(); + + let second = timings.snapshot(); + assert_eq!( + second.auction_dispatched_ms, first.auction_dispatched_ms, + "should not restamp the dispatch offset" + ); + assert_eq!( + second.auction_resolved_ms, first.auction_resolved_ms, + "should not restamp the resolve offset" + ); + assert_eq!( + second.auction_committed_ms, first.auction_committed_ms, + "should not restamp the commit offset" + ); + assert_eq!( + second.auction_id, + Some(uuid::uuid!("11111111-1111-1111-1111-111111111111")), + "should keep the first-recorded auction id" + ); + } + + #[test] + fn auction_id_survives_a_dropped_dispatch_mark() { + // The join key is stamped where the observation is built, so an + // auction that is skipped or fails to dispatch still carries the id + // that its `auction_events_raw` row was emitted under. + let timings = RequestTimings::new(); + timings.set_auction_id(uuid::uuid!("44444444-4444-4444-4444-444444444444")); + + let snapshot = timings.snapshot(); + assert_eq!( + snapshot.auction_id, + Some(uuid::uuid!("44444444-4444-4444-4444-444444444444")), + "should carry the join key without a dispatch mark" + ); + assert_eq!( + snapshot.auction_dispatched_ms, None, + "should leave the dispatch offset null when nothing was sent" + ); + } + + #[test] + fn snapshot_without_auction_marks_yields_none_for_all_offsets() { + let timings = RequestTimings::new(); + timings.mark_headers_ready(); + let snapshot = timings.snapshot(); + assert_eq!( + snapshot.auction_dispatched_ms, None, + "should stay None when no auction dispatched" + ); + assert_eq!( + snapshot.auction_resolved_ms, None, + "should stay None when no auction resolved" + ); + assert_eq!( + snapshot.auction_committed_ms, None, + "should stay None when no auction committed" + ); + assert_eq!( + snapshot.auction_id, None, + "should carry no auction id when no auction ran" + ); + } + #[test] fn render_omits_unrecorded_phases_and_orders_total_first() { let timings = RequestTimings::new(); diff --git a/docs/superpowers/plans/2026-08-26-auction-timeline-offsets.md b/docs/superpowers/plans/2026-08-26-auction-timeline-offsets.md new file mode 100644 index 000000000..6a2aec751 --- /dev/null +++ b/docs/superpowers/plans/2026-08-26-auction-timeline-offsets.md @@ -0,0 +1,83 @@ +# Auction Timeline Offsets Implementation Plan + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** Record three T0-anchored auction milestones (dispatched, resolved, committed) plus the auction id on `RequestTimings`, and emit them as four additive columns on the `access_logs_raw` row. + +**Architecture:** Follows spec section 18. All state lives in the existing `RequestTimings` inner (same `try_lock`/first-call-wins/saturating model as `mark_headers_ready`); the row builder reads the values from `TimingSnapshot`, so no new emission path and no adapter changes. + +**Tech Stack:** Rust (core crate only), Tinybird datasource and fixture files. + +**Spec:** `docs/superpowers/specs/2026-08-24-request-phase-timing-design.md` section 18. + +## Global Constraints + +- Marks are first-call-wins; `try_lock` only; a contended lock drops the sample, a poisoned lock is recovered (matching every other write on the collector). +- A null offset means "this milestone was not reached", not "no auction ran". `auction_id` is what separates the two: null id means no auction was attempted; a non-null id with a null dispatch offset means attempted but nothing sent; a non-null dispatch offset with a null resolve offset means dispatched and never collected. +- The id is stamped where the observation is built, not on dispatch, so skipped and dispatch-failed auctions stay joinable to the `auction_events_raw` rows they emit. +- Column names: `auction_dispatched_ms`, `auction_resolved_ms`, `auction_committed_ms`, `auction_id`; JSONPaths `json:$.`; FORWARD_QUERY extended in the same order. +- `auction_id` is `Nullable(UUID)`, matching `auction_events_raw.auction_id` so the join needs no cast and no sentinel. +- All three `AuctionSource` variants are instrumented: `InitialNavigation`, `SpaNavigation` (`/_ts/page-bids`), and `AuctionApi` (`POST /auction`). +- No header emission and no config surface. Changes are confined to `trusted-server-core`, `tinybird/`, and the spec and plan documents. + +--- + +### Task 1: RequestTimings marks and snapshot fields + +**Files:** + +- Modify: `crates/trusted-server-core/src/request_timing.rs` + +**Interfaces:** + +- Produces: `set_auction_id(&self, auction_id: Uuid)`, `mark_auction_dispatched(&self)`, `mark_auction_resolved(&self)`, `mark_auction_committed(&self)`; `TimingSnapshot { auction_dispatched_ms, auction_resolved_ms, auction_committed_ms: Option, auction_id: Option, .. }` + +- [x] Add `auction_dispatched`, `auction_resolved`, `auction_committed: Option` and `auction_id: Option` to `Inner`; initialize `None`. +- [x] Add `set_auction_id` plus the three no-arg mark methods, first-call-wins on their own field, storing `inner.t0.elapsed()`. +- [x] Recover a poisoned lock in all four, matching the other lock-taking methods on the collector. +- [x] Map all four into `TimingSnapshot` via `duration_ms`; `Uuid` is `Copy`, so the id needs no clone. +- [x] Tests: first-call-wins per mark, proved by sleeping between the two calls and asserting the value is unchanged; the id survives a request with no dispatch mark; unmarked snapshot yields all `None`. +- [x] `cargo test-fastly request_timing`, commit. + +### Task 2: Auction call sites + +**Files:** + +- Modify: `crates/trusted-server-core/src/publisher.rs` +- Modify: `crates/trusted-server-core/src/auction/endpoints.rs` + +**Interfaces:** + +- Consumes: Task 1 methods; `observation.auction_id` (`AuctionObservationContext`), in scope wherever an observation is built. + +- [x] Navigation path: `set_auction_id` at observation construction; `mark_auction_dispatched()` in the `DispatchAuctionOutcome::Dispatched` arm; `mark_auction_resolved()` after both `record_auction_wait` calls; `mark_auction_committed()` after both `write_bids_to_state` calls. +- [x] `/_ts/page-bids`: pull the collector off the request extensions; `set_auction_id` at observation construction; dispatch before `run_auction`, resolve on both its `Ok` and `Err` arms, commit after the bid map is built. +- [x] `POST /auction`: pull the collector off `parts.extensions` (the request is consumed by `into_parts` before the auction runs); same bracket around `run_auction`, commit once the OpenRTB response is converted. +- [x] Tests: extend the two existing collect-site tests to assert the resolve and commit offsets alongside `auction_wait_ms`. +- [x] `cargo test-fastly`, commit. + +### Task 3: Row columns, datasource, fixture + +**Files:** + +- Modify: `crates/trusted-server-core/src/access_telemetry.rs` +- Modify: `tinybird/datasources/access_logs_raw.datasource` +- Modify: `tinybird/fixtures/access_logs_raw.ndjson` + +- [x] `access_event_row`: add the three offset keys and `auction_id`, all nullable, after the existing phase keys. +- [x] Extend `row_serializes_nulls_for_missing_phases` (including `auction_id` in the nullable-column loop) and `row_serializes_recorded_phases_as_numbers` for the new keys. +- [x] Datasource: four schema columns with JSONPaths (`Nullable(UInt32)` ×3, `Nullable(UUID)`), appended at the end of SCHEMA and FORWARD_QUERY so existing column order stays stable. +- [x] Fixture: extend the existing row with a full timeline reusing the `auction_events_raw` fixture's UUID so the pair demonstrates the join, and add a second row covering the no-auction case. +- [x] Full gates: fmt, clippy (all six), test-fastly/axum/cloudflare/spin, parity. Commit. + +### Task 4: Spec amendment + +**Files:** + +- Modify: `docs/superpowers/specs/2026-08-24-request-phase-timing-design.md` + +- [x] Section 18: mark table including `set_auction_id`, the per-source instrumentation table, the null-semantics table, and the `Nullable(UUID)` rationale. +- [x] Section 18: correct the interpretation ladder so `time_elapsed_ms` is not shown last, since on a streamed body the headers commit before the seam collect. +- [x] Section 18: state the `R - D` versus `total_time_ms` reconciliation caveat and give the join query. +- [x] Section 9: add the four columns so the canonical column list the row builder's doc comment points at stays complete. +- [x] Docs format (`cd docs && npm run format`). diff --git a/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md b/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md index 3833e81eb..61d43e273 100644 --- a/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md +++ b/docs/superpowers/specs/2026-08-24-request-phase-timing-design.md @@ -335,9 +335,16 @@ ClickHouse sorting keys cannot contain nullable columns): `template_cache_state` LowCardinality(String), -- from the typed response extension, not the public header `country` LowCardinality(String), `ts_version` LowCardinality(String), -`pop` LowCardinality(String) -- FASTLY_POP, 'unknown' when absent +`pop` LowCardinality(String), -- FASTLY_POP, 'unknown' when absent +`auction_dispatched_ms` Nullable(UInt32), -- section 18 +`auction_resolved_ms` Nullable(UInt32), -- section 18 +`auction_committed_ms` Nullable(UInt32), -- section 18 +`auction_id` Nullable(UUID) -- section 18; join key to auction_events_raw ``` +The four auction columns are specified in section 18; they are listed here so +this block stays the single canonical column list. + The matched route pattern does not survive dispatch today, so a typed `RouteMetadata` response extension carries `route_class` and `route_template`: each named-route handler wrapper attaches its route-table pattern verbatim (handlers @@ -575,3 +582,181 @@ streamed. No allocation in the hot path beyond the one `Arc` at entry, the - The stall window itself remains unattributed until this ships. If it recurs first, the bisection runbook from 2026-08-21 (cookie-free curl UA request, static-asset path versus HTML path) is the fallback. + +## 18. Auction timeline offsets (follow-up increment) + +Status: spec amendment written ahead of implementation, then implemented in the +same PR on top of the initial implementation (#1074). Builds only on machinery +that spec sections 5, 9, and 10 already define. + +### Problem + +The pipeline has two clocks that never meet. The auction dataset +(`auction_events_raw`, PR #813) measures the auction internally: `total_time_ms` +from auction start to terminal, `provider_response_time_ms` per bidder call. Its +clock starts when the auction observation is created, so nothing places those +numbers on the request timeline. The access row is T0-anchored but records only +`auction_wait_ms`: time the handler was blocked at collect, deliberately not the +auction's own timeline. + +That leaves three questions unanswerable today: + +1. At what request-relative time did the auction start (dispatch leave the edge)? +2. At what request-relative time did the auction resolve (final bid or timeout)? +3. At what request-relative time were the results committed toward GAM? + +These are the overlap-proof questions. A client-side wrapper cannot dispatch until +the browser boots (t~3000ms on measured prospect pages); the server-side auction +dispatches while the origin fetch is in flight. Proving that requires all +milestones on one clock. + +### Design + +One first-call-wins id setter and three first-call-wins marks on +`RequestTimings`, in the style of `mark_headers_ready()`, each mark storing +`Option` since T0: + +| Call | Recorded at | Meaning | +| --------------------------- | ---------------------------------------------------------------------------- | ----------------------------------------------------- | +| `set_auction_id()` | where the `AuctionObservationContext` is built, on all three auction sources | the join key to `auction_events_raw` for this request | +| `mark_auction_dispatched()` | where the bid requests leave the edge | bid requests have left the edge | +| `mark_auction_resolved()` | where the auction returns, terminal on success, failure, or timeout | final bid returned or auction timed out | +| `mark_auction_committed()` | where winning bids become available to the response pipeline | targeting is committed | + +All three auction sources are instrumented, because all three emit rows to +`auction_events_raw` and all three emit an access row: + +| Source | Route | Dispatch / resolve bracket | Commit | +| ------------------- | ---------------- | ---------------------------- | -------------------------- | +| `InitialNavigation` | publisher HTML | `dispatch_auction` / collect | `write_bids_to_state` | +| `SpaNavigation` | `/_ts/page-bids` | `run_auction` | bid map built | +| `AuctionApi` | `POST /auction` | `run_auction` | OpenRTB response converted | + +Notes on the definitions: + +- "Committed toward GAM" is defined as the point where targeting becomes part of + the response: `write_bids_to_state` returning on the navigation path, the bid + map on page-bids, the converted OpenRTB response on `/auction`. TS never calls + GAM server-side; the browser's GPT call carries the targeting, and that half of + the timeline belongs to client-side measurement. The edge proves when targeting + was available; the client proves when GAM saw it. +- The id is set separately from the dispatch mark, and earlier. Every auction + outcome emits an `auction_events_raw` row under that id, including skipped and + dispatch-failed auctions, so stamping the id at dispatch would leave exactly + those rows unjoinable. It also means a dropped dispatch sample cannot take the + join key with it. +- First-call-wins on the id and all three marks. A request produces at most one + auction today; if a second ever occurs in one request, the row describes the + first and the auction dataset still carries both in full. +- Same locking and failure model as every other `RequestTimings` write: + `try_lock`, drop on contention, poisoned lock recovered, saturating conversion + at serialization. + +### Row changes + +Four additive columns on `access_logs_raw`, all populated from the +`TimingSnapshot` at the existing freeze/emission points (no new emission path): + +``` +`auction_dispatched_ms` Nullable(UInt32), `json:$.auction_dispatched_ms` +`auction_resolved_ms` Nullable(UInt32), `json:$.auction_resolved_ms` +`auction_committed_ms` Nullable(UInt32), `json:$.auction_committed_ms` +`auction_id` Nullable(UUID), `json:$.auction_id` +``` + +Null on an offset means "this milestone was not reached", not "no auction ran". +`auction_id` is what separates the cases, and the two read together: + +| `auction_id` | `dispatched` | `resolved` | Meaning | +| ------------ | ------------ | ---------- | ----------------------------------------------------------- | +| null | null | null | no auction was attempted (assets, EC endpoints, disabled) | +| set | null | null | attempted, then skipped or failed to dispatch | +| set | set | null | dispatched, never collected (origin error, 304, disconnect) | +| set | set | set | ran to completion or timed out | + +The third row is the case worth watching: bid requests went out and the response +they were for never used them. It is distinguishable now, where before it was +indistinguishable from "no auction". + +- `auction_id` is the telemetry auction UUID already present on every + `auction_events_raw` row, carried onto the access row as the join key between + the T0 timeline and per-bidder detail. It is `Nullable(UUID)` rather than a + String with a sentinel so it joins natively against `auction_events_raw` + .`auction_id`, which is `UUID`: a String column would make the join a type + error, and casting a `'none'` sentinel through `toUUID` throws. It is a random + UUID, not identity-bearing; unbounded cardinality is accepted for the same + reason it is accepted in the auction dataset. It is not in the sorting key, so + the section 9 non-nullable-dimension rule (which exists because ClickHouse + sorting keys cannot contain nullable columns) does not apply to it. +- Schema evolution is additive with JSONPaths on every new column and + `FORWARD_QUERY` carrying the existing columns, per the deployed datasource's + established evolution path. Verified with `tb --cloud deploy --check` before + deploy. + +### Interpretation model + +Combined with existing columns, one access row now reads as a timeline: + +``` +t=0 ......... request entry +t=D ......... auction_dispatched_ms (bids out; origin fetch typically in flight) +t=R ......... auction_resolved_ms (R - D ~ auction duration; join auction_id + for the per-bidder long pole) +t=C ......... auction_committed_ms (targeting available to the response) +``` + +`time_elapsed_ms` (t=H, headers committed) does **not** belong at the end of that +ladder, and where it lands depends on `body_mode`: + +- Buffered (`auction_wait_placement = 'pre_header'`): H comes after C. The auction + is collected before the response headers are built, so D < R < C < H. +- Streamed (`auction_wait_placement = 'in_stream'`): H comes **before** R and C. + `mark_headers_ready` is stamped at the terminal layer before the lazy body is + polled, while the collect happens at the `` seam inside that body. So + D < H < R < C is the normal ordering for a streamed HTML page. + +A sanity filter of the form `auction_committed_ms <= time_elapsed_ms` therefore +discards every valid streamed row. Slice by `body_mode` before comparing the +auction marks against H at all. + +Derivations the dashboard can add without schema help: auction duration on the +request clock (`R - D`), commit latency (`C - R`), and overlap ratio (share of +`R - D` that ran concurrently with `ts-origin`). `C - R` is whole-millisecond +like every other column here, and on the navigation path it brackets +`write_bids_to_state`, whose cost is per-winning-bid creative processing +(sanitize, first-party URL rewrite, signing, with `rewrite_creatives` on by +default). Expect 0 on light auctions and non-zero as creative count and size +grow; it is not a restatement of `R`. `auction_wait_ms` keeps its existing +meaning (blocked time only) and is now interpretable next to the timeline: +`R - D` minus `auction_wait_ms` approximates how much of the auction was +absorbed by work the request needed anyway. + +Joining to per-bidder detail, now that both sides are `UUID`: + +```sql +SELECT a.auction_id, a.auction_resolved_ms - a.auction_dispatched_ms AS edge_window, + e.provider, e.provider_response_time_ms +FROM access_logs_raw a +INNER JOIN auction_events_raw e ON a.auction_id = e.auction_id +WHERE a.auction_id IS NOT NULL AND e.event_kind = 'provider_call' +``` + +One caveat on reconciling the two clocks: D is stamped where dispatch returns to +the caller, while the auction dataset's `total_time_ms` and +`provider_response_time_ms` start inside the orchestrator's launch loop. So +`R - D` is the post-launch window and can read slightly smaller than a joined +per-provider time. Treat `R - D` as the request-clock cost of the auction, and +the auction dataset as the authority on per-bidder duration. + +### Scope + +- Fastly emits. Axum attaches a collector and records the marks but does not + emit them. Cloudflare and Spin attach no collector at all: `handle_publisher_request` + falls back to `RequestTimings::default()`, so the marks land in a throwaway + handle and are dropped with it. That is pre-existing for every phase, not new + to these marks, and it matches section 8a adapter semantics. +- No header emission for any of these values: they are post-hoc analysis fields, + and two of the three are typically unknown at the header freeze point in + streaming mode. +- No config surface: the marks are always-on collection like every other phase, + gated at emission by the existing `tinybird.access_enabled`. diff --git a/tinybird/datasources/access_logs_raw.datasource b/tinybird/datasources/access_logs_raw.datasource index 062b884ba..2815feb15 100644 --- a/tinybird/datasources/access_logs_raw.datasource +++ b/tinybird/datasources/access_logs_raw.datasource @@ -27,13 +27,17 @@ SCHEMA > `template_cache_state` LowCardinality(String) `json:$.template_cache_state`, `country` LowCardinality(String) `json:$.country`, `ts_version` LowCardinality(String) `json:$.ts_version`, - `pop` LowCardinality(String) `json:$.pop` + `pop` LowCardinality(String) `json:$.pop`, + `auction_dispatched_ms` Nullable(UInt32) `json:$.auction_dispatched_ms`, + `auction_resolved_ms` Nullable(UInt32) `json:$.auction_resolved_ms`, + `auction_committed_ms` Nullable(UInt32) `json:$.auction_committed_ms`, + `auction_id` Nullable(UUID) `json:$.auction_id` ENGINE "MergeTree" ENGINE_SORTING_KEY "toDate(event_ts), service_id, publisher_domain, env, route_class, pop, status" TTL "toDate(event_ts) + INTERVAL 30 DAY" FORWARD_QUERY > - SELECT event_ts, method, status, time_elapsed_ms, sample_rate, service_id, publisher_domain, env, route_class, route_template, body_mode, auction_wait_placement, appbuild_ms, filter_ms, geo_ms, kv_ms, origin_ms, template_cache_ms, auction_wait_ms, stream_ms, request_elapsed_ms, resp_bytes, template_cache_state, country, ts_version, pop + SELECT event_ts, method, status, time_elapsed_ms, sample_rate, service_id, publisher_domain, env, route_class, route_template, body_mode, auction_wait_placement, appbuild_ms, filter_ms, geo_ms, kv_ms, origin_ms, template_cache_ms, auction_wait_ms, stream_ms, request_elapsed_ms, resp_bytes, template_cache_state, country, ts_version, pop, CAST(NULL AS Nullable(UInt32)) AS auction_dispatched_ms, CAST(NULL AS Nullable(UInt32)) AS auction_resolved_ms, CAST(NULL AS Nullable(UInt32)) AS auction_committed_ms, CAST(NULL AS Nullable(UUID)) AS auction_id TOKEN ts_access_ingest APPEND diff --git a/tinybird/fixtures/access_logs_raw.ndjson b/tinybird/fixtures/access_logs_raw.ndjson index 983b3acd1..ad408624d 100644 --- a/tinybird/fixtures/access_logs_raw.ndjson +++ b/tinybird/fixtures/access_logs_raw.ndjson @@ -1 +1,2 @@ -{"event_ts":"2026-06-23 12:00:00.000","method":"GET","status":200,"time_elapsed_ms":145,"sample_rate":0.1,"service_id":"abc123","publisher_domain":"test-publisher.example","env":"production","route_class":"publisher_html","route_template":"/news/*","body_mode":"streamed","auction_wait_placement":"in_stream","appbuild_ms":12,"filter_ms":5,"geo_ms":3,"kv_ms":8,"origin_ms":25,"template_cache_ms":10,"auction_wait_ms":45,"stream_ms":18,"request_elapsed_ms":145,"resp_bytes":8192,"template_cache_state":"hit","country":"US","ts_version":"v1.2.3","pop":"SFO"} +{"event_ts":"2026-06-23 12:00:00.000","method":"GET","status":200,"time_elapsed_ms":145,"sample_rate":0.1,"service_id":"abc123","publisher_domain":"test-publisher.example","env":"production","route_class":"publisher_html","route_template":"/news/*","body_mode":"streamed","auction_wait_placement":"in_stream","appbuild_ms":12,"filter_ms":5,"geo_ms":3,"kv_ms":8,"origin_ms":25,"template_cache_ms":10,"auction_wait_ms":45,"stream_ms":18,"request_elapsed_ms":145,"resp_bytes":8192,"template_cache_state":"hit","country":"US","ts_version":"v1.2.3","pop":"SFO","auction_dispatched_ms":30,"auction_resolved_ms":92,"auction_committed_ms":94,"auction_id":"550e8400-e29b-41d4-a716-446655440000"} +{"event_ts":"2026-06-23 12:00:01.000","method":"GET","status":200,"time_elapsed_ms":12,"sample_rate":0.1,"service_id":"abc123","publisher_domain":"test-publisher.example","env":"production","route_class":"asset","route_template":"/static/*","body_mode":"streamed","auction_wait_placement":"none","appbuild_ms":2,"filter_ms":1,"geo_ms":null,"kv_ms":null,"origin_ms":8,"template_cache_ms":null,"auction_wait_ms":null,"stream_ms":3,"request_elapsed_ms":12,"resp_bytes":2048,"template_cache_state":"bypass","country":"US","ts_version":"v1.2.3","pop":"SFO","auction_dispatched_ms":null,"auction_resolved_ms":null,"auction_committed_ms":null,"auction_id":null}