From 274241b9ebb0f9bcabff420bc56a3a82ab1920a0 Mon Sep 17 00:00:00 2001 From: Jason Evans Date: Wed, 26 Aug 2026 11:00:29 -0700 Subject: [PATCH 1/4] Add auction timeline offsets spec amendment Adds section 18 to the request phase timing spec: three first-call-wins T0 offsets (auction dispatched, resolved, committed) on RequestTimings, emitted as additive nullable columns on access_logs_raw with auction_id as the join key to the per-bidder auction dataset. Answers the overlap-proof questions the two existing clocks cannot: when the auction started relative to request entry, when the final bid landed, and when targeting was committed toward GAM. --- .../2026-08-24-request-phase-timing-design.md | 105 ++++++++++++++++++ 1 file changed, 105 insertions(+) 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 214d146a1..56c2685b3 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 @@ -562,3 +562,108 @@ 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 for a follow-up PR; not part 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 + +Three first-call-wins marks on `RequestTimings`, in the style of +`mark_headers_ready()`, each storing `Option` since T0: + +| Mark | Recorded at | Meaning | +| --------------------------- | --------------------------------------------------------------------------------------------------------------- | ------------------------------------------------------------------ | +| `mark_auction_dispatched()` | immediately before `orchestrator.dispatch_auction` returns control to the caller (`publisher.rs` dispatch site) | bid requests have left the edge | +| `mark_auction_resolved()` | immediately after `collect_dispatched_auction` returns, both collect sites | final bid returned or auction timed out; terminal either way | +| `mark_auction_committed()` | immediately after `write_bids_to_state` returns, both call sites | winning bids are in page state, available to the response pipeline | + +Notes on the definitions: + +- "Committed toward GAM" is defined as `write_bids_to_state` returning: the common + point in buffered and streaming modes where targeting becomes part of the + response. 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. +- First-call-wins on all three marks. A request produces at most one publisher-path + auction today; if a second auction 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, 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` String, `json:$.auction_id` +``` + +- The three offsets are null when no auction ran (the common case: assets, EC + endpoints, auction-disabled deployments). Null means "no auction", never "zero". +- `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. Sentinel `none` when no auction ran, + matching the non-nullable-dimension convention of section 9. It is a random + UUID, not identity-bearing; unbounded cardinality is accepted for the same + reason it is accepted in the auction dataset. +- 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 in page state) +t=H ......... time_elapsed_ms (headers committed) +``` + +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`). `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. + +### Scope + +- Fastly emits; Axum, Cloudflare, and Spin collect the marks but do not emit, + matching 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`. From 29d45e8c8087173ef8daa221898892b58a399989 Mon Sep 17 00:00:00 2001 From: Jason Evans Date: Wed, 26 Aug 2026 11:31:09 -0700 Subject: [PATCH 2/4] Add auction timeline offsets implementation plan --- .../2026-08-26-auction-timeline-offsets.md | 59 +++++++++++++++++++ 1 file changed, 59 insertions(+) create mode 100644 docs/superpowers/plans/2026-08-26-auction-timeline-offsets.md 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..08e14dabc --- /dev/null +++ b/docs/superpowers/plans/2026-08-26-auction-timeline-offsets.md @@ -0,0 +1,59 @@ +# 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 exactly. 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 file. + +**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. +- Null offsets mean "no auction ran", never zero. `auction_id` sentinel is `none`. +- Column names: `auction_dispatched_ms`, `auction_resolved_ms`, `auction_committed_ms`, `auction_id`; JSONPaths `json:$.`; FORWARD_QUERY extended in the same order. +- Dispatch mark records only on `DispatchAuctionOutcome::Dispatched`; a failed dispatch leaves all three offsets null (the auction dataset still records the failure). +- No header emission, no config surface, no changes outside `trusted-server-core` and `tinybird/`. + +--- + +### Task 1: RequestTimings marks and snapshot fields + +**Files:** +- Modify: `crates/trusted-server-core/src/request_timing.rs` + +**Interfaces:** +- Produces: `mark_auction_dispatched(&self, auction_id: String)`, `mark_auction_resolved(&self)`, `mark_auction_committed(&self)`; `TimingSnapshot { auction_dispatched_ms, auction_resolved_ms, auction_committed_ms: Option, auction_id: Option, .. }` + +- [ ] Add `auction_dispatched`, `auction_resolved`, `auction_committed: Option` and `auction_id: Option` to `Inner`; initialize `None`. +- [ ] Add the three mark methods, first-call-wins on their own field, storing `inner.t0.elapsed()`; dispatched also stores the id first-call-wins. +- [ ] Map all four into `TimingSnapshot` via `duration_ms` / clone. +- [ ] Tests: first-call-wins per mark; snapshot maps offsets and id; unmarked snapshot yields all `None`. +- [ ] `cargo test-fastly request_timing`, commit. + +### Task 2: Publisher call sites + +**Files:** +- Modify: `crates/trusted-server-core/src/publisher.rs` + +**Interfaces:** +- Consumes: Task 1 methods; `observation.auction_id` (`AuctionObservationContext`), in scope at the dispatch site. + +- [ ] In the `DispatchAuctionOutcome::Dispatched` arm (~line 4341): `timings.mark_auction_dispatched(observation.auction_id.to_string());` +- [ ] After both `record_auction_wait` calls (collect sites ~3952 and ~4012): `mark_auction_resolved()`. +- [ ] After both `write_bids_to_state` calls (~3954 and ~4017): `mark_auction_committed()`. +- [ ] `cargo test-fastly`, commit. + +### Task 3: Row columns and datasource + +**Files:** +- Modify: `crates/trusted-server-core/src/access_telemetry.rs` +- Modify: `tinybird/datasources/access_logs_raw.datasource` + +- [ ] `access_event_row`: add the three offset keys (nullable) and `auction_id` with `none` sentinel, after the existing phase keys. +- [ ] Extend `row_serializes_nulls_for_missing_phases` and `row_serializes_recorded_phases_as_numbers` for the new keys. +- [ ] Datasource: four schema columns with JSONPaths (`Nullable(UInt32)` ×3, `String`), appended at the end of SCHEMA and FORWARD_QUERY so existing column order stays stable. +- [ ] Full gates: fmt, clippy (all six), test-fastly/axum/cloudflare/spin, parity. Commit. From 46911a647347adc13791171995839e43a92c56fb Mon Sep 17 00:00:00 2001 From: Jason Evans Date: Wed, 26 Aug 2026 11:31:09 -0700 Subject: [PATCH 3/4] Record T0-anchored auction timeline offsets in the access row Implements spec section 18: three first-call-wins marks on RequestTimings (dispatched at the DispatchAuctionOutcome::Dispatched arm, resolved after collect at both sites, committed after write_bids_to_state at both sites), carried through TimingSnapshot into four additive access_logs_raw columns: auction_dispatched_ms, auction_resolved_ms, auction_committed_ms, and auction_id as the join key to the per-bidder auction dataset. Null offsets mean no auction ran; a failed dispatch records nothing. FORWARD_QUERY fills the new columns with typed defaults for pre-existing rows. No header emission, no config surface, no adapter changes: the values ride the existing snapshot and the tinybird.access_enabled gate. --- .../wrangler.integration.generated.toml | 16 +++ .../src/access_telemetry.rs | 19 +++ crates/trusted-server-core/src/publisher.rs | 14 ++ .../trusted-server-core/src/request_timing.rs | 134 ++++++++++++++++++ .../datasources/access_logs_raw.datasource | 8 +- 5 files changed, 189 insertions(+), 2 deletions(-) create mode 100644 crates/trusted-server-adapter-cloudflare/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 new file mode 100644 index 000000000..263403193 --- /dev/null +++ b/crates/trusted-server-adapter-cloudflare/wrangler.integration.generated.toml @@ -0,0 +1,16 @@ +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 2aac6d7d3..083adbe8e 100644 --- a/crates/trusted-server-core/src/access_telemetry.rs +++ b/crates/trusted-server-core/src/access_telemetry.rs @@ -286,6 +286,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.as_deref().unwrap_or("none"), "template_cache_state": snapshot.template_cache_state, "country": snapshot.country, "ts_version": snapshot.ts_version, @@ -463,6 +467,9 @@ mod tests { "stream_ms", "request_elapsed_ms", "resp_bytes", + "auction_dispatched_ms", + "auction_resolved_ms", + "auction_committed_ms", ] { assert!( parsed[field].is_null(), @@ -488,6 +495,10 @@ mod tests { ); } assert_eq!(parsed["auction_wait_placement"], "none"); + assert_eq!( + parsed["auction_id"], "none", + "auction_id should carry the none sentinel when no auction ran" + ); } #[test] @@ -506,6 +517,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("33333333-3333-3333-3333-333333333333".to_owned()), }; let row = access_event_row(&snapshot, &timings, 1_700_000_000_000); let parsed: serde_json::Value = @@ -515,6 +530,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/publisher.rs b/crates/trusted-server-core/src/publisher.rs index 53d09bfc6..3981c386b 100644 --- a/crates/trusted-server-core/src/publisher.rs +++ b/crates/trusted-server-core/src/publisher.rs @@ -3951,6 +3951,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, @@ -3960,6 +3962,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()) { @@ -4010,6 +4015,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() @@ -4023,6 +4030,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()) { @@ -4340,6 +4350,10 @@ pub async fn handle_publisher_request( .await { DispatchAuctionOutcome::Dispatched(dispatched) => { + // T0-anchored timeline mark (spec section 18): bid + // requests have left the edge. A failed dispatch never + // marks, so all three auction offsets stay null for it. + timings.mark_auction_dispatched(observation.auction_id.to_string()); auction_request_for_telemetry = Some(auction_request); auction_observation = Some(observation); Some(dispatched) diff --git a/crates/trusted-server-core/src/request_timing.rs b/crates/trusted-server-core/src/request_timing.rs index 8d1b92cc1..edcd9bfc2 100644 --- a/crates/trusted-server-core/src/request_timing.rs +++ b/crates/trusted-server-core/src/request_timing.rs @@ -106,6 +106,19 @@ 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::mark_auction_dispatched`] call; joins the access + /// row to the per-bidder auction dataset. + auction_id: Option, } /// Per-request phase timing collector. @@ -128,6 +141,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, }))) } @@ -200,6 +217,53 @@ impl RequestTimings { } } + /// Stamps the elapsed time since `t0` as the auction dispatch offset and + /// records the telemetry auction id, the first time this is called. + /// + /// Called when `dispatch_auction` reports the bid requests dispatched; + /// a failed dispatch never records, so all three auction offsets stay + /// `None` for it. Subsequent calls are no-ops (first call wins). Drops + /// the sample silently on lock contention or poisoning. + pub fn mark_auction_dispatched(&self, auction_id: String) { + let Ok(mut inner) = self.0.try_lock() else { + return; + }; + if inner.auction_dispatched.is_none() { + inner.auction_dispatched = Some(inner.t0.elapsed()); + inner.auction_id = Some(auction_id); + } + } + + /// 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. + /// + /// Subsequent calls are no-ops (first call wins). Drops the sample + /// silently on lock contention or poisoning. + pub fn mark_auction_resolved(&self) { + let Ok(mut inner) = self.0.try_lock() else { + 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 written into page state), the first time this is + /// called. + /// + /// Subsequent calls are no-ops (first call wins). Drops the sample + /// silently on lock contention or poisoning. + pub fn mark_auction_committed(&self) { + let Ok(mut inner) = self.0.try_lock() else { + 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 or poisoning. @@ -257,6 +321,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.clone(), } } } @@ -379,6 +447,18 @@ 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), or `None` when no auction ran. + pub auction_dispatched_ms: Option, + /// T0 offset at which the auction resolved (final bid or timeout), or + /// `None` when no auction ran. + pub auction_resolved_ms: Option, + /// T0 offset at which winning bids were committed into page state, or + /// `None` when no auction ran. + pub auction_committed_ms: Option, + /// Telemetry auction UUID joining this row to the auction dataset, or + /// `None` when no auction ran. + pub auction_id: Option, } #[cfg(test)] @@ -419,6 +499,60 @@ mod tests { ); } + #[test] + fn auction_marks_are_first_call_wins_and_snapshot_maps_them() { + let timings = RequestTimings::new(); + timings.mark_auction_dispatched("11111111-1111-1111-1111-111111111111".to_owned()); + timings.mark_auction_resolved(); + timings.mark_auction_committed(); + // Second calls must not overwrite the first-recorded values. + timings.mark_auction_dispatched("22222222-2222-2222-2222-222222222222".to_owned()); + timings.mark_auction_resolved(); + timings.mark_auction_committed(); + + let snapshot = timings.snapshot(); + assert!( + snapshot.auction_dispatched_ms.is_some(), + "should record the dispatch offset" + ); + assert!( + snapshot.auction_resolved_ms.is_some(), + "should record the resolve offset" + ); + assert!( + snapshot.auction_committed_ms.is_some(), + "should record the commit offset" + ); + assert_eq!( + snapshot.auction_id.as_deref(), + Some("11111111-1111-1111-1111-111111111111"), + "should keep the first-recorded auction id" + ); + } + + #[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/tinybird/datasources/access_logs_raw.datasource b/tinybird/datasources/access_logs_raw.datasource index 062b884ba..4441de384 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` String `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, 'none' AS auction_id TOKEN ts_access_ingest APPEND From 1fa9f8cc09df889aec42039b13b7a108d1df9d47 Mon Sep 17 00:00:00 2001 From: Jason Evans Date: Wed, 26 Aug 2026 11:31:29 -0700 Subject: [PATCH 4/4] Remove generated integration wrangler config from tracking The Cloudflare integration harness writes wrangler.integration.generated.toml at test time; it was swept into the previous commit by accident. Ignore it so local CI=1 runs cannot commit it again. --- .gitignore | 1 + .../wrangler.integration.generated.toml | 16 ---------------- 2 files changed, 1 insertion(+), 16 deletions(-) delete mode 100644 crates/trusted-server-adapter-cloudflare/wrangler.integration.generated.toml diff --git a/.gitignore b/.gitignore index 24b9e06aa..96ffa2a5c 100644 --- a/.gitignore +++ b/.gitignore @@ -63,3 +63,4 @@ src/*.html # leftover local build artifacts (node_modules, target, dist) that remain on disk. /crates/js/ /crates/integration-tests/ +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}"}'''