From 8aebc9fd9f721461954155906e89168a66b95b64 Mon Sep 17 00:00:00 2001 From: tornquist Date: Fri, 4 Sep 2026 17:29:30 +0000 Subject: [PATCH 01/17] fix(relay): make readiness local and stop dropping sockets on DB errors MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A reconnect burst exhausted the per-pod writer pools and two feedback loops turned that into a total outage. Readiness evaluated shared Postgres, Redis, and deletion-catalog health, so every replica went NotReady together and the burst had nowhere to land. The probe was also part of the load: the deletion-catalog check acquires the writer pool, so each pod spent writer connections against the exhausted pool every five seconds while failing. /_readiness now answers from local process lifecycle only — shutting_down is 503, anything else is 200 — and the dependency evaluation moves to /_status on the same private health listener, under a `dependencies` object carrying the fields the readiness body used to return. No startup state is added: the health listener binds only after the database, migrations, Redis, and pub/sub are up, so a process that can answer has booted. run_registered_community_connection collapsed Ok(false) and Err into "not active", so a writer-pool timeout in is_community_active read as confirmed archival and dropped the socket, which reconnected and re-checked. Only a confirmed Ok(false) cancels now; a lookup failure admits the socket with a structured warning and defers to the periodic revalidate_live_communities backstop. Writes are unaffected and remain fail-closed on their own per-event fence. Telemetry keeps its existing names: buzz_readiness_checks_total narrows to {ready, shutting_down}, the dependency families are now sampled by /_status, dependency gauges are dropped, and one new bounded counter, buzz_community_admission_checks_total{outcome}, counts the admission decision. The per-pod raw-series ceiling drops from 99 to 86. This deletes the readiness publication machinery — the mutex, probe generations, ProbeTicket/ProbeStart, finish_probe, finish_public_evaluation, and a second shutdown flag duplicating AppState::shutting_down. All of it existed to order concurrent async dependency evaluations against shutdown. Readiness is now a single atomic load, so the one ordering guarantee still worth keeping — a racing shutdown must win, and never leave a draining pod advertising a ready gauge — is a post-write re-read in record_readiness_probe rather than a generation-fenced mutex. Co-authored-by: Claude Code Redis had no startup gate at all. `deadpool_redis` pools dial lazily and PubSubManager::new only allocates channels, so "Redis pub/sub connected" was logged against a dead port and boot ran to completion. With readiness now answering from local lifecycle alone, such a pod bound its health listener and advertised ready for the rest of its life. state:: verify_redis_command_path acquires one connection from the command pool and issues PING before AppState is built, and therefore before the health listener binds, because binding is the one-way latch that makes a pod routable. No startup_ready flag is added for the same reason. Post-start Redis failures are unchanged: they are dependency failures and never move readiness. Postgres startup connection behavior is untouched. Signed-off-by: tornquist --- ARCHITECTURE.md | 2 +- crates/buzz-relay/src/main.rs | 8 +- crates/buzz-relay/src/metrics.rs | 24 +- crates/buzz-relay/src/readiness.rs | 628 +++++++++------------- crates/buzz-relay/src/router.rs | 620 +++++++++------------ crates/buzz-relay/src/state.rs | 255 ++++++++- crates/buzz-relay/tests/boot_lifecycle.rs | 89 +++ deploy/charts/buzz/README.md | 67 ++- docs/deployment-identity.md | 11 + 9 files changed, 932 insertions(+), 772 deletions(-) diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index ae82c131ec7..ed34ee4c8d3 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -644,7 +644,7 @@ pub enum AuthState { Pending { challenge: String }, Authenticated(AuthContext), | GET | `/.well-known/nostr.json` | NIP-05 identity | | GET | `/health` | Health check | | GET | `/_liveness` | Liveness probe | -| GET | `/_readiness` | Readiness probe | +| GET | `/_readiness` | Readiness probe — local process lifecycle only | | POST | `/events` | Submit a signed Nostr event over HTTP (same ingest path as WebSocket `EVENT`) | | POST | `/query` | Query Nostr events over HTTP with NIP-01 filters | | POST | `/count` | Count Nostr events over HTTP with NIP-45 filters | diff --git a/crates/buzz-relay/src/main.rs b/crates/buzz-relay/src/main.rs index 6adea419da1..cf34af60159 100644 --- a/crates/buzz-relay/src/main.rs +++ b/crates/buzz-relay/src/main.rs @@ -455,7 +455,13 @@ async fn run_relay_main(boot: BootTracker) -> anyhow::Result<()> { cfg.create_pool(Some(deadpool_redis::Runtime::Tokio1)) .map_err(|e| anyhow::anyhow!("Redis pool creation failed: {e}"))? }; - let redis_health_pool = redis_pool.clone(); // cheap Arc clone — shared with readiness handler + let redis_health_pool = redis_pool.clone(); // cheap Arc clone — shared with AppState + // One-time bootstrap gate, deliberately before AppState and therefore before + // the health listener binds. Post-start Redis failures are dependency + // failures and must never move readiness; never having connected at all is + // a broken deployment, not a blip. + buzz_relay::state::verify_redis_command_path(&redis_health_pool).await?; + info!("Redis command path connected"); let pubsub = Arc::new( PubSubManager::new(&config.redis_url, redis_pool) .await diff --git a/crates/buzz-relay/src/metrics.rs b/crates/buzz-relay/src/metrics.rs index c1e72f7b75a..bed10e68c3b 100644 --- a/crates/buzz-relay/src/metrics.rs +++ b/crates/buzz-relay/src/metrics.rs @@ -290,6 +290,7 @@ pub fn try_install(port: u16, gauge_idle_timeout_secs: u64) -> Result<(), Metric metrics::set_global_recorder(recorder) .map_err(|_error| MetricsInstallError::RecorderConflict)?; describe_readiness_metrics(); + describe_community_admission_metrics(); describe_db_pool_metrics(); describe_auth_metrics(); initialize_auth_metric_series(); @@ -306,24 +307,37 @@ pub fn install(port: u16, gauge_idle_timeout_secs: u64) { .unwrap_or_else(|error| panic!("metrics exporter must install exactly once: {error}")); } -/// Register the frozen readiness metric descriptions with the active recorder. +/// Register the frozen readiness and dependency-diagnostic metric descriptions. +/// +/// The two `buzz_readiness_*` probe families describe local process lifecycle. +/// The two dependency families keep their names for dashboard continuity but +/// are sampled by the diagnostic `/_status` endpoint, not by the Kubernetes +/// probe — a shared-dependency failure no longer deroutes the pod. pub(crate) fn describe_readiness_metrics() { metrics::describe_counter!( "buzz_readiness_checks_total", - "Kubernetes health-listener readiness probes by terminal bounded reason" + "Kubernetes health-listener readiness probes by lifecycle reason (ready, shutting_down)" ); metrics::describe_counter!( "buzz_readiness_dependency_checks_total", - "Completed readiness dependency attempts by dependency and bounded outcome" + "Completed /_status dependency attempts by dependency and bounded outcome" ); metrics::describe_histogram!( "buzz_readiness_check_duration_seconds", metrics::Unit::Seconds, - "Completed readiness check duration without outcome label multiplication" + "Completed /_status dependency check duration without outcome label multiplication" ); metrics::describe_gauge!( "buzz_readiness_state", - "Latest publishable readiness state by check, where 1 is ready and 0 is not ready" + "Local readiness of this process, where 1 is ready and 0 is shutting down" + ); +} + +/// Register the bounded community-admission contract. +pub(crate) fn describe_community_admission_metrics() { + metrics::describe_counter!( + "buzz_community_admission_checks_total", + "Durable community-active checks at socket admission by bounded outcome" ); } diff --git a/crates/buzz-relay/src/readiness.rs b/crates/buzz-relay/src/readiness.rs index 79a1a985707..c64f29407b9 100644 --- a/crates/buzz-relay/src/readiness.rs +++ b/crates/buzz-relay/src/readiness.rs @@ -1,43 +1,88 @@ -//! Readiness dependency evaluation and ordered metrics publication. +//! Readiness-probe telemetry and the dependency diagnostics behind `/_status`. //! -//! [`ReadinessCoordinator`] is process-owned. Its mutex is the linearization -//! point shared by health-probe commits and terminal shutdown, so an older -//! evaluation can never overwrite newer gauges or publish ready after shutdown. +//! Readiness is deliberately *not* a dependency question. A shared Postgres or +//! Redis failure is shared by every replica, so evaluating it in the probe took +//! the whole deployment out of the load balancer at once and left a reconnect +//! burst with nowhere to land. The Kubernetes probe therefore answers from this +//! process's own lifecycle (see [`crate::router`]), and the same dependency +//! evaluation is reported on the diagnostic `/_status` endpoint, which is never +//! wired to a probe. use std::future::Future; -use std::sync::{Arc, Mutex, MutexGuard, PoisonError}; +use std::sync::Arc; use std::time::Duration; use buzz_db::{Db, DbError, DbReadinessOutcome}; use tokio::time::Instant; -const READINESS_TIMEOUT: Duration = Duration::from_secs(2); +const DEPENDENCY_TIMEOUT: Duration = Duration::from_secs(2); /// Closed label set exported by `buzz_readiness_checks_total{reason}`. +/// +/// Readiness answers a local lifecycle question, so this set cannot grow with +/// the number of shared dependencies the relay talks to. #[cfg(test)] -pub(crate) const READINESS_REASON_LABELS: [&str; 12] = [ - "ready", - "shutting_down", - "postgres_pool_timeout", - "postgres_pool_error", - "postgres_query_timeout", - "postgres_query_error", - "redis_pool_timeout", - "redis_pool_error", - "deletion_catalog_timeout", - "deletion_catalog_error", - "overall_timeout", - "multiple_dependencies_failed", -]; - -/// Maximum raw Prometheus series emitted by readiness for one pod. +pub(crate) const READINESS_REASON_LABELS: [&str; 2] = ["ready", "shutting_down"]; + +/// Maximum raw Prometheus series emitted by readiness and its dependency +/// diagnostics for one pod. /// -/// - 12 overall reasons +/// - 2 probe reasons /// - 11 valid dependency/outcome pairs (Postgres 5, Redis 3, catalog 3) /// - 4 histograms x (15 configured buckets + `+Inf` + count + sum) = 72 -/// - 4 current-state gauges +/// - 1 overall readiness gauge #[cfg(test)] -pub(crate) const READINESS_RAW_SERIES_PER_POD: usize = 12 + 11 + (4 * 18) + 4; +pub(crate) const READINESS_RAW_SERIES_PER_POD: usize = 2 + 11 + (4 * 18) + 1; + +/// Terminal outcome of one readiness probe. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub(crate) enum ReadinessReason { + Ready, + ShuttingDown, +} + +impl ReadinessReason { + pub(crate) fn label(self) -> &'static str { + match self { + Self::Ready => "ready", + Self::ShuttingDown => "shutting_down", + } + } + + pub(crate) fn is_ready(self) -> bool { + self == Self::Ready + } +} + +/// Records one readiness probe served by the private health listener. +/// +/// `still_ready` re-reads process lifecycle *after* the gauge is written. That +/// ordering is the whole fence: `begin_shutdown` is one-way, so a probe that +/// sampled `Ready` immediately before it must not leave a stale ready gauge +/// behind for the rest of the drain. Re-reading before the write would reopen +/// the same window. Nothing else about a probe is shared, so this replaces the +/// generation-fenced coordinator the dependency probe used to require. +pub(crate) fn record_readiness_probe(reason: ReadinessReason, still_ready: impl FnOnce() -> bool) { + metrics::counter!( + "buzz_readiness_checks_total", + "reason" => reason.label(), + ) + .increment(1); + record_overall_state(reason.is_ready()); + if !still_ready() { + record_overall_state(false); + } +} + +/// Publishes the overall readiness gauge. Called by the probe and by terminal +/// shutdown, so a draining pod reports not-ready before its next scrape. +pub(crate) fn record_overall_state(ready: bool) { + metrics::gauge!("buzz_readiness_state", "check" => "overall").set(if ready { + 1.0 + } else { + 0.0 + }); +} #[derive(Debug, Clone, Copy, PartialEq, Eq)] pub(crate) enum PostgresOutcome { @@ -130,10 +175,14 @@ impl DeletionCatalogOutcome { } } +/// Aggregate dependency verdict reported in the `/_status` diagnostics body. +/// +/// This is a diagnostic field, never a metric label: it exists so an operator +/// reading `/_status` gets the same one-line summary the readiness body used to +/// carry. #[derive(Debug, Clone, Copy, PartialEq, Eq)] -pub(crate) enum ReadinessReason { +pub(crate) enum DependencyReason { Ready, - ShuttingDown, PostgresPoolTimeout, PostgresPoolError, PostgresQueryTimeout, @@ -146,11 +195,10 @@ pub(crate) enum ReadinessReason { MultipleDependenciesFailed, } -impl ReadinessReason { +impl DependencyReason { pub(crate) fn label(self) -> &'static str { match self { Self::Ready => "ready", - Self::ShuttingDown => "shutting_down", Self::PostgresPoolTimeout => "postgres_pool_timeout", Self::PostgresPoolError => "postgres_pool_error", Self::PostgresQueryTimeout => "postgres_query_timeout", @@ -178,26 +226,18 @@ impl TimedOutcome { } } +/// One completed dependency evaluation. Every dependency always runs, so the +/// report carries three outcomes and never a partial shape. #[derive(Debug, Clone, Copy)] -pub(crate) struct ReadinessEvaluation { - postgres: Option>, - redis: Option>, - deletion_catalog: Option>, - pub(crate) reason: ReadinessReason, +pub(crate) struct DependencyReport { + postgres: TimedOutcome, + redis: TimedOutcome, + deletion_catalog: TimedOutcome, + pub(crate) reason: DependencyReason, total_duration: Duration, } -impl ReadinessEvaluation { - pub(crate) fn shutting_down() -> Self { - Self { - postgres: None, - redis: None, - deletion_catalog: None, - reason: ReadinessReason::ShuttingDown, - total_duration: Duration::ZERO, - } - } - +impl DependencyReport { #[cfg(test)] pub(crate) fn from_results( postgres: TimedOutcome, @@ -216,34 +256,24 @@ impl ReadinessEvaluation { ) -> Self { let reason = final_reason(postgres.outcome, redis.outcome, deletion_catalog.outcome); Self { - postgres: Some(postgres), - redis: Some(redis), - deletion_catalog: Some(deletion_catalog), + postgres, + redis, + deletion_catalog, reason, total_duration, } } - pub(crate) fn is_ready(self) -> bool { - self.reason == ReadinessReason::Ready - } - pub(crate) fn postgres_ready(self) -> bool { - self.postgres - .is_some_and(|result| result.outcome.is_success()) + self.postgres.outcome.is_success() } pub(crate) fn redis_ready(self) -> bool { - self.redis.is_some_and(|result| result.outcome.is_success()) + self.redis.outcome.is_success() } pub(crate) fn deletion_catalog_ready(self) -> bool { - self.deletion_catalog - .is_some_and(|result| result.outcome.is_success()) - } - - fn dependencies_ran(self) -> bool { - self.postgres.is_some() || self.redis.is_some() || self.deletion_catalog.is_some() + self.deletion_catalog.outcome.is_success() } } @@ -251,37 +281,39 @@ fn final_reason( postgres: PostgresOutcome, redis: RedisOutcome, deletion_catalog: DeletionCatalogOutcome, -) -> ReadinessReason { +) -> DependencyReason { let failure_count = usize::from(!postgres.is_success()) + usize::from(!redis.is_success()) + usize::from(!deletion_catalog.is_success()); if failure_count == 0 { - return ReadinessReason::Ready; + return DependencyReason::Ready; } if failure_count > 1 { let all_failures_are_timeouts = (postgres.is_success() || postgres.is_timeout()) && (redis.is_success() || redis.is_timeout()) && (deletion_catalog.is_success() || deletion_catalog.is_timeout()); return if all_failures_are_timeouts { - ReadinessReason::OverallTimeout + DependencyReason::OverallTimeout } else { - ReadinessReason::MultipleDependenciesFailed + DependencyReason::MultipleDependenciesFailed }; } match postgres { - PostgresOutcome::PoolTimeout => ReadinessReason::PostgresPoolTimeout, - PostgresOutcome::PoolError => ReadinessReason::PostgresPoolError, - PostgresOutcome::QueryTimeout => ReadinessReason::PostgresQueryTimeout, - PostgresOutcome::QueryError => ReadinessReason::PostgresQueryError, + PostgresOutcome::PoolTimeout => DependencyReason::PostgresPoolTimeout, + PostgresOutcome::PoolError => DependencyReason::PostgresPoolError, + PostgresOutcome::QueryTimeout => DependencyReason::PostgresQueryTimeout, + PostgresOutcome::QueryError => DependencyReason::PostgresQueryError, PostgresOutcome::Success => match redis { - RedisOutcome::PoolTimeout => ReadinessReason::RedisPoolTimeout, - RedisOutcome::PoolError => ReadinessReason::RedisPoolError, + RedisOutcome::PoolTimeout => DependencyReason::RedisPoolTimeout, + RedisOutcome::PoolError => DependencyReason::RedisPoolError, RedisOutcome::Success => match deletion_catalog { - DeletionCatalogOutcome::OperationTimeout => ReadinessReason::DeletionCatalogTimeout, - DeletionCatalogOutcome::OperationError => ReadinessReason::DeletionCatalogError, - DeletionCatalogOutcome::Success => ReadinessReason::Ready, + DeletionCatalogOutcome::OperationTimeout => { + DependencyReason::DeletionCatalogTimeout + } + DeletionCatalogOutcome::OperationError => DependencyReason::DeletionCatalogError, + DeletionCatalogOutcome::Success => DependencyReason::Ready, }, }, } @@ -303,7 +335,7 @@ async fn evaluate_dependencies( postgres: P, redis: R, deletion_catalog: D, -) -> ReadinessEvaluation +) -> DependencyReport where P: Future, R: Future, @@ -312,7 +344,7 @@ where let started_at = Instant::now(); let (postgres, redis, deletion_catalog) = tokio::join!(timed(postgres), timed(redis), timed(deletion_catalog),); - ReadinessEvaluation::for_dependencies(postgres, redis, deletion_catalog, started_at.elapsed()) + DependencyReport::for_dependencies(postgres, redis, deletion_catalog, started_at.elapsed()) } async fn redis_check(pool: &deadpool_redis::Pool, deadline: Instant) -> RedisOutcome { @@ -345,16 +377,16 @@ fn classify_deletion_catalog_result(result: buzz_db::Result<()>) -> DeletionCata } #[async_trait::async_trait] -pub(crate) trait ReadinessEvaluator: Send + Sync { - async fn evaluate(&self, db: &Db, redis_pool: &deadpool_redis::Pool) -> ReadinessEvaluation; +pub(crate) trait DependencyEvaluator: Send + Sync { + async fn evaluate(&self, db: &Db, redis_pool: &deadpool_redis::Pool) -> DependencyReport; } -struct ProductionReadinessEvaluator; +struct ProductionDependencyEvaluator; #[async_trait::async_trait] -impl ReadinessEvaluator for ProductionReadinessEvaluator { - async fn evaluate(&self, db: &Db, redis_pool: &deadpool_redis::Pool) -> ReadinessEvaluation { - let deadline = Instant::now() + READINESS_TIMEOUT; +impl DependencyEvaluator for ProductionDependencyEvaluator { + async fn evaluate(&self, db: &Db, redis_pool: &deadpool_redis::Pool) -> DependencyReport { + let deadline = Instant::now() + DEPENDENCY_TIMEOUT; evaluate_dependencies( async { db.readiness_check(deadline).await.into() }, redis_check(redis_pool, deadline), @@ -364,150 +396,63 @@ impl ReadinessEvaluator for ProductionReadinessEvaluator { } } -#[derive(Debug, Clone, Copy)] -pub(crate) struct ProbeTicket { - generation: u64, -} - -#[derive(Debug, Clone, Copy)] -pub(crate) enum ProbeStart { - Evaluate(ProbeTicket), - ShuttingDown, -} - -#[derive(Debug, Default)] -struct PublicationState { - next_generation: u64, - latest_published_generation: u64, - shutdown_generation: Option, -} - -/// Serializes readiness result publication with terminal process shutdown. -pub(crate) struct ReadinessCoordinator { - state: Mutex, - evaluator: Arc, +/// Evaluates shared-dependency health for the diagnostic `/_status` endpoint. +/// +/// This deliberately owns no publication fence. It publishes no gauge, so two +/// concurrent `/_status` requests cannot reorder any shared state — the fence +/// the readiness coordinator used to need went away with the dependency probe. +pub(crate) struct DependencyDiagnostics { + evaluator: Arc, } -impl Default for ReadinessCoordinator { +impl Default for DependencyDiagnostics { fn default() -> Self { Self { - state: Mutex::new(PublicationState::default()), - evaluator: Arc::new(ProductionReadinessEvaluator), + evaluator: Arc::new(ProductionDependencyEvaluator), } } } -impl ReadinessCoordinator { +impl DependencyDiagnostics { #[cfg(test)] - pub(crate) fn with_evaluator(evaluator: Arc) -> Self { - Self { - state: Mutex::new(PublicationState::default()), - evaluator, - } - } - - fn lock_state(&self) -> MutexGuard<'_, PublicationState> { - self.state.lock().unwrap_or_else(PoisonError::into_inner) + pub(crate) fn with_evaluator(evaluator: Arc) -> Self { + Self { evaluator } } + /// Runs one bounded dependency evaluation and records its telemetry. pub(crate) async fn evaluate( &self, db: &Db, redis_pool: &deadpool_redis::Pool, - ) -> ReadinessEvaluation { - self.evaluator.evaluate(db, redis_pool).await - } - - /// Allocates a health-probe generation or records a truthful shutdown fast path. - pub(crate) fn begin_probe(&self) -> ProbeStart { - let mut state = self.lock_state(); - if state.shutdown_generation.is_some() { - let evaluation = ReadinessEvaluation::shutting_down(); - record_attempt_metrics(&evaluation, ReadinessReason::ShuttingDown); - record_overall_state(false); - return ProbeStart::ShuttingDown; - } - - state.next_generation = state.next_generation.saturating_add(1); - ProbeStart::Evaluate(ProbeTicket { - generation: state.next_generation, - }) - } - - /// Commits one completed health probe through the shared publication fence. - pub(crate) fn finish_probe( - &self, - ticket: ProbeTicket, - evaluation: ReadinessEvaluation, - ) -> ReadinessEvaluation { - let mut state = self.lock_state(); - if state.shutdown_generation.is_some() { - record_attempt_metrics(&evaluation, ReadinessReason::ShuttingDown); - return ReadinessEvaluation::shutting_down(); - } - - record_attempt_metrics(&evaluation, evaluation.reason); - if ticket.generation > state.latest_published_generation { - record_current_state(&evaluation); - state.latest_published_generation = ticket.generation; - } - evaluation - } - - /// Returns whether a compatibility/public readiness evaluation may start. - pub(crate) fn public_evaluation_allowed(&self) -> bool { - self.lock_state().shutdown_generation.is_none() - } - - /// Makes shutdown dominate a public request that was already in flight. - pub(crate) fn finish_public_evaluation( - &self, - evaluation: ReadinessEvaluation, - ) -> ReadinessEvaluation { - if self.lock_state().shutdown_generation.is_some() { - ReadinessEvaluation::shutting_down() - } else { - evaluation - } - } - - /// Commits terminal shutdown and immediately publishes overall not-ready. - pub(crate) fn begin_shutdown(&self) { - let mut state = self.lock_state(); - if state.shutdown_generation.is_none() { - let generation = state.next_generation.saturating_add(1); - state.shutdown_generation = Some(generation); - record_overall_state(false); - } + ) -> DependencyReport { + let report = self.evaluator.evaluate(db, redis_pool).await; + record_dependency_report(&report); + report } } -fn record_attempt_metrics(evaluation: &ReadinessEvaluation, reason: ReadinessReason) { - metrics::counter!( - "buzz_readiness_checks_total", - "reason" => reason.label(), - ) - .increment(1); - - if !evaluation.dependencies_ran() { - return; - } - +/// Records one dependency evaluation. Counters and durations only — dependency +/// health has no publishable "current state" now that no probe consumes it, and +/// a gauge driven by ad-hoc `/_status` requests would read as authoritative +/// while going stale between operator visits. +fn record_dependency_report(report: &DependencyReport) { metrics::histogram!( "buzz_readiness_check_duration_seconds", "check" => "overall", ) - .record(evaluation.total_duration.as_secs_f64()); + .record(report.total_duration.as_secs_f64()); - if let Some(result) = evaluation.postgres { - record_dependency_attempt("postgres", result.outcome.label(), result.duration); - } - if let Some(result) = evaluation.redis { - record_dependency_attempt("redis", result.outcome.label(), result.duration); - } - if let Some(result) = evaluation.deletion_catalog { - record_dependency_attempt("deletion_catalog", result.outcome.label(), result.duration); - } + record_dependency_attempt( + "postgres", + report.postgres.outcome.label(), + report.postgres.duration, + ); + record_dependency_attempt("redis", report.redis.outcome.label(), report.redis.duration); + record_dependency_attempt( + "deletion_catalog", + report.deletion_catalog.outcome.label(), + report.deletion_catalog.duration, + ); } fn record_dependency_attempt(dependency: &'static str, outcome: &'static str, duration: Duration) { @@ -524,35 +469,6 @@ fn record_dependency_attempt(dependency: &'static str, outcome: &'static str, du .record(duration.as_secs_f64()); } -fn record_current_state(evaluation: &ReadinessEvaluation) { - record_overall_state(evaluation.is_ready()); - if let Some(result) = evaluation.postgres { - record_dependency_state("postgres", result.outcome.is_success()); - } - if let Some(result) = evaluation.redis { - record_dependency_state("redis", result.outcome.is_success()); - } - if let Some(result) = evaluation.deletion_catalog { - record_dependency_state("deletion_catalog", result.outcome.is_success()); - } -} - -fn record_overall_state(ready: bool) { - metrics::gauge!("buzz_readiness_state", "check" => "overall").set(if ready { - 1.0 - } else { - 0.0 - }); -} - -fn record_dependency_state(dependency: &'static str, ready: bool) { - metrics::gauge!("buzz_readiness_state", "check" => dependency).set(if ready { - 1.0 - } else { - 0.0 - }); -} - #[cfg(test)] mod tests { use metrics_util::debugging::{DebugValue, DebuggingRecorder}; @@ -560,17 +476,15 @@ mod tests { use super::*; - fn ready_evaluation() -> ReadinessEvaluation { - ReadinessEvaluation::from_results( - TimedOutcome::new(PostgresOutcome::Success, Duration::from_millis(35)), - TimedOutcome::new(RedisOutcome::Success, Duration::from_millis(10)), - TimedOutcome::new(DeletionCatalogOutcome::Success, Duration::from_millis(20)), - Duration::from_millis(35), - ) - } + type Snapshot = Vec<( + CompositeKey, + Option, + Option, + DebugValue, + )>; - fn redis_failure_evaluation() -> ReadinessEvaluation { - ReadinessEvaluation::from_results( + fn redis_failure_report() -> DependencyReport { + DependencyReport::from_results( TimedOutcome::new(PostgresOutcome::Success, Duration::from_millis(35)), TimedOutcome::new(RedisOutcome::PoolTimeout, Duration::from_secs(2)), TimedOutcome::new(DeletionCatalogOutcome::Success, Duration::from_millis(20)), @@ -579,12 +493,7 @@ mod tests { } fn exact_metric<'a>( - snapshot: &'a [( - CompositeKey, - Option, - Option, - DebugValue, - )], + snapshot: &'a Snapshot, name: &str, labels: &[(&str, &str)], ) -> Option<&'a DebugValue> { @@ -601,15 +510,7 @@ mod tests { }) } - fn gauge_value( - snapshot: &[( - CompositeKey, - Option, - Option, - DebugValue, - )], - check: &str, - ) -> f64 { + fn gauge_value(snapshot: &Snapshot, check: &str) -> f64 { let value = exact_metric(snapshot, "buzz_readiness_state", &[("check", check)]) .expect("readiness gauge"); let DebugValue::Gauge(value) = value else { @@ -620,7 +521,7 @@ mod tests { #[tokio::test(start_paused = true)] async fn evaluation_preserves_a_completed_check_when_another_times_out() { - let evaluation = evaluate_dependencies( + let report = evaluate_dependencies( async { tokio::time::sleep(Duration::from_millis(35)).await; PostgresOutcome::Success @@ -636,15 +537,9 @@ mod tests { ) .await; - assert_eq!(evaluation.reason, ReadinessReason::RedisPoolTimeout); - assert_eq!( - evaluation.postgres.map(|result| result.duration), - Some(Duration::from_millis(35)) - ); - assert_eq!( - evaluation.redis.map(|result| result.duration), - Some(Duration::from_secs(2)) - ); + assert_eq!(report.reason, DependencyReason::RedisPoolTimeout); + assert_eq!(report.postgres.duration, Duration::from_millis(35)); + assert_eq!(report.redis.duration, Duration::from_secs(2)); } #[test] @@ -655,7 +550,7 @@ mod tests { RedisOutcome::PoolTimeout, DeletionCatalogOutcome::Success, ), - ReadinessReason::OverallTimeout + DependencyReason::OverallTimeout ); } @@ -696,7 +591,7 @@ mod tests { .map(DeletionCatalogOutcome::label), ["success", "operation_timeout", "operation_error"] ); - assert_eq!(READINESS_RAW_SERIES_PER_POD, 99); + assert_eq!(READINESS_RAW_SERIES_PER_POD, 86); } #[test] @@ -711,145 +606,134 @@ mod tests { ); } + /// The readiness gauge and counter follow lifecycle only. A dependency + /// evaluation — however bad — must never move them, which is what let a + /// shared outage deroute every replica at once. #[test] - fn slow_older_failure_cannot_overwrite_newer_success_gauges() { - let coordinator = ReadinessCoordinator::default(); - let ProbeStart::Evaluate(slow_a) = coordinator.begin_probe() else { - panic!("serving probe A"); - }; - let ProbeStart::Evaluate(fast_b) = coordinator.begin_probe() else { - panic!("serving probe B"); - }; + fn readiness_telemetry_tracks_lifecycle_and_dependency_failure_never_moves_it() { let recorder = DebuggingRecorder::new(); let snapshotter = recorder.snapshotter(); metrics::with_local_recorder(&recorder, || { - coordinator.finish_probe(fast_b, ready_evaluation()); - coordinator.finish_probe(slow_a, redis_failure_evaluation()); + record_readiness_probe(ReadinessReason::Ready, || true); + record_dependency_report(&redis_failure_report()); }); - let snapshot = snapshotter.snapshot().into_vec(); + let after_failure = snapshotter.snapshot().into_vec(); - assert_eq!(gauge_value(&snapshot, "overall"), 1.0); - assert_eq!(gauge_value(&snapshot, "redis"), 1.0); + assert_eq!(gauge_value(&after_failure, "overall"), 1.0); assert!(matches!( exact_metric( - &snapshot, + &after_failure, "buzz_readiness_checks_total", &[("reason", "ready")] ), Some(DebugValue::Counter(1)) )); + assert!( + matches!( + exact_metric( + &after_failure, + "buzz_readiness_dependency_checks_total", + &[("dependency", "redis"), ("outcome", "pool_timeout")] + ), + Some(DebugValue::Counter(1)) + ), + "dependency diagnostics must still be counted" + ); + for dependency in ["postgres", "redis", "deletion_catalog"] { + assert!( + exact_metric( + &after_failure, + "buzz_readiness_state", + &[("check", dependency)] + ) + .is_none(), + "{dependency} must not publish a readiness gauge" + ); + } + + metrics::with_local_recorder(&recorder, || { + record_readiness_probe(ReadinessReason::ShuttingDown, || false); + }); + let after_shutdown = snapshotter.snapshot().into_vec(); + + assert_eq!(gauge_value(&after_shutdown, "overall"), 0.0); assert!(matches!( exact_metric( - &snapshot, + &after_shutdown, "buzz_readiness_checks_total", - &[("reason", "redis_pool_timeout")] + &[("reason", "shutting_down")] ), Some(DebugValue::Counter(1)) )); } + /// The publication fence. A probe that sampled `Ready` a moment before + /// `begin_shutdown` landed must not leave the gauge advertising ready for + /// the rest of the drain. Deleting the post-write re-read fails the first + /// case below. #[test] - fn slow_older_success_cannot_overwrite_newer_failure_gauges() { - let coordinator = ReadinessCoordinator::default(); - let ProbeStart::Evaluate(slow_a) = coordinator.begin_probe() else { - panic!("serving probe A"); - }; - let ProbeStart::Evaluate(fast_b) = coordinator.begin_probe() else { - panic!("serving probe B"); - }; - let recorder = DebuggingRecorder::new(); - let snapshotter = recorder.snapshotter(); - - metrics::with_local_recorder(&recorder, || { - coordinator.finish_probe(fast_b, redis_failure_evaluation()); - coordinator.finish_probe(slow_a, ready_evaluation()); - }); - let snapshot = snapshotter.snapshot().into_vec(); - - assert_eq!(gauge_value(&snapshot, "overall"), 0.0); - assert_eq!(gauge_value(&snapshot, "postgres"), 1.0); - assert_eq!(gauge_value(&snapshot, "redis"), 0.0); - assert_eq!(gauge_value(&snapshot, "deletion_catalog"), 1.0); - } - - #[test] - fn shutdown_fast_path_preserves_dependency_state_and_histograms() { - let coordinator = ReadinessCoordinator::default(); - let recorder = DebuggingRecorder::new(); - let snapshotter = recorder.snapshotter(); - - metrics::with_local_recorder(&recorder, || { - let ProbeStart::Evaluate(ticket) = coordinator.begin_probe() else { - panic!("initial serving probe"); - }; - coordinator.finish_probe(ticket, ready_evaluation()); - coordinator.begin_shutdown(); - assert!(matches!( - coordinator.begin_probe(), - ProbeStart::ShuttingDown - )); - }); - let after = snapshotter.snapshot().into_vec(); + fn a_probe_that_raced_shutdown_cannot_leave_a_ready_gauge() { + for (sampled, still_ready, expected, case) in [ + ( + ReadinessReason::Ready, + false, + 0.0, + "shutdown landed mid-probe", + ), + (ReadinessReason::Ready, true, 1.0, "no shutdown"), + ( + ReadinessReason::ShuttingDown, + false, + 0.0, + "already draining", + ), + ( + ReadinessReason::ShuttingDown, + true, + 0.0, + "sampled shutdown never publishes ready", + ), + ] { + let recorder = DebuggingRecorder::new(); + let snapshotter = recorder.snapshotter(); + metrics::with_local_recorder(&recorder, || { + record_readiness_probe(sampled, || still_ready); + }); - for dependency in ["postgres", "redis", "deletion_catalog"] { assert_eq!( - gauge_value(&after, dependency), - 1.0, - "shutdown must not fabricate {dependency} state" + gauge_value(&snapshotter.snapshot().into_vec(), "overall"), + expected, + "{case}" ); } - for check in ["overall", "postgres", "redis", "deletion_catalog"] { - assert!( - matches!( - exact_metric( - &after, - "buzz_readiness_check_duration_seconds", - &[("check", check)] - ), - Some(DebugValue::Histogram(values)) if values.len() == 1 - ), - "shutdown fast path must not add a {check} duration" - ); - } - assert_eq!(gauge_value(&after, "overall"), 0.0); - assert!(matches!( - exact_metric( - &after, - "buzz_readiness_checks_total", - &[("reason", "shutting_down")] - ), - Some(DebugValue::Counter(1)) - )); } + /// A shutdown probe records no dependency attempt or latency sample: it did + /// not evaluate anything, and fabricating a sample would misreport the + /// dependency's real health during a rollout. #[test] - fn shutdown_dominates_an_in_flight_success_without_resurrecting_gauges() { - let coordinator = ReadinessCoordinator::default(); - let ProbeStart::Evaluate(ticket) = coordinator.begin_probe() else { - panic!("serving probe"); - }; + fn a_readiness_probe_never_records_dependency_attempts() { let recorder = DebuggingRecorder::new(); let snapshotter = recorder.snapshotter(); - let response = metrics::with_local_recorder(&recorder, || { - coordinator.begin_shutdown(); - coordinator.finish_probe(ticket, ready_evaluation()) + metrics::with_local_recorder(&recorder, || { + record_readiness_probe(ReadinessReason::Ready, || true); + record_readiness_probe(ReadinessReason::ShuttingDown, || false); }); let snapshot = snapshotter.snapshot().into_vec(); - assert_eq!(response.reason, ReadinessReason::ShuttingDown); - assert_eq!(gauge_value(&snapshot, "overall"), 0.0); - assert!( - exact_metric(&snapshot, "buzz_readiness_state", &[("check", "postgres")]).is_none() + assert!(snapshot.iter().all(|(key, _, _, _)| { + key.key().name() != "buzz_readiness_dependency_checks_total" + && key.key().name() != "buzz_readiness_check_duration_seconds" + })); + } + + #[test] + fn readiness_reason_labels_are_the_closed_lifecycle_set() { + assert_eq!( + [ReadinessReason::Ready, ReadinessReason::ShuttingDown].map(ReadinessReason::label), + READINESS_REASON_LABELS ); - assert!(matches!( - exact_metric( - &snapshot, - "buzz_readiness_dependency_checks_total", - &[("dependency", "postgres"), ("outcome", "success")] - ), - Some(DebugValue::Counter(1)) - )); } } diff --git a/crates/buzz-relay/src/router.rs b/crates/buzz-relay/src/router.rs index 303ecff82f0..15b520c0673 100644 --- a/crates/buzz-relay/src/router.rs +++ b/crates/buzz-relay/src/router.rs @@ -25,7 +25,7 @@ use crate::connection::handle_connection; use crate::metrics::track_metrics; use crate::nip11::{nip11_document, relay_info_handler}; use crate::nip_fi_http::http_denial; -use crate::readiness::{self, ReadinessEvaluation, ReadinessReason}; +use crate::readiness::{self, DependencyReport, ReadinessReason}; use crate::state::AppState; // ── NIP-FI fail-closed assertion guard ─────────────────────────────────────── @@ -645,60 +645,47 @@ async fn liveness_handler() -> impl IntoResponse { (StatusCode::OK, "ok") } -/// Compatibility endpoint on the public listener. It evaluates dependencies -/// and preserves the existing response contract but never records rollout -/// telemetry. +/// Compatibility endpoint on the public listener. Same lifecycle answer as the +/// probe, but public traffic must never move rollout telemetry. async fn public_readiness_handler(State(state): State>) -> impl IntoResponse { - if !state.readiness.public_evaluation_allowed() { - return readiness_response(ReadinessEvaluation::shutting_down(), false); - } - - let evaluation = state.readiness.evaluate(&state.db, &state.redis_pool).await; - let evaluation = state.readiness.finish_public_evaluation(evaluation); - readiness_response(evaluation, false) + readiness_response(readiness_reason(&state)) } -/// Kubernetes health-listener endpoint. All rollout metrics flow through the -/// process-owned coordinator so shutdown and probe generations are ordered. +/// Kubernetes health-listener endpoint — the only source of rollout readiness +/// telemetry. async fn kubernetes_readiness_handler(State(state): State>) -> impl IntoResponse { - let readiness::ProbeStart::Evaluate(ticket) = state.readiness.begin_probe() else { - return readiness_response(ReadinessEvaluation::shutting_down(), true); - }; + let reason = readiness_reason(&state); + readiness::record_readiness_probe(reason, || readiness_reason(&state).is_ready()); + readiness_response(reason) +} - let evaluation = state.readiness.evaluate(&state.db, &state.redis_pool).await; - let evaluation = state.readiness.finish_probe(ticket, evaluation); - readiness_response(evaluation, true) +/// Readiness answers for this process only. +/// +/// Shared Postgres, Redis, and deletion-catalog health used to gate this +/// answer, which meant one shared outage removed every replica from the load +/// balancer simultaneously and left a reconnect burst with nowhere to land. +/// Those checks now report on `/_status`. The health listener does not bind +/// until the database, migrations, Redis, and pub/sub are up (see +/// `buzz-relay/src/main.rs`), so an answering process is a booted process and +/// needs no separate startup state. +fn readiness_reason(state: &AppState) -> ReadinessReason { + if state.shutting_down.load(Ordering::Acquire) { + ReadinessReason::ShuttingDown + } else { + ReadinessReason::Ready + } } -fn readiness_response( - evaluation: ReadinessEvaluation, - include_reason: bool, -) -> axum::response::Response { - if evaluation.reason == ReadinessReason::ShuttingDown { - return ( +fn readiness_response(reason: ReadinessReason) -> axum::response::Response { + match reason { + ReadinessReason::Ready => { + (StatusCode::OK, Json(json!({"status": "ready"}))).into_response() + } + ReadinessReason::ShuttingDown => ( StatusCode::SERVICE_UNAVAILABLE, Json(json!({"status": "shutting_down"})), ) - .into_response(); - } - - let pg_ok = evaluation.postgres_ready(); - let redis_ok = evaluation.redis_ready(); - let deletion_catalog_ok = evaluation.deletion_catalog_ready(); - - if evaluation.is_ready() { - (StatusCode::OK, Json(json!({"status": "ready"}))).into_response() - } else { - let mut payload = json!({ - "status": "not_ready", - "postgres": pg_ok, - "redis": redis_ok, - "deletion_catalog": deletion_catalog_ok - }); - if include_reason { - payload["reason"] = json!(evaluation.reason.label()); - } - (StatusCode::SERVICE_UNAVAILABLE, Json(payload)).into_response() + .into_response(), } } @@ -715,9 +702,30 @@ fn status_payload(uptime_secs: u64) -> serde_json::Value { }) } -/// Status endpoint — service name, version, uptime, and intrinsic build identity. +/// The dependency fields the readiness body used to carry, now diagnostic only. +fn dependency_diagnostics_payload(report: &DependencyReport) -> serde_json::Value { + json!({ + "postgres": report.postgres_ready(), + "redis": report.redis_ready(), + "deletion_catalog": report.deletion_catalog_ready(), + "reason": report.reason.label(), + }) +} + +/// Status endpoint — service name, version, uptime, intrinsic build identity, +/// and shared-dependency diagnostics. +/// +/// Health-listener only, and never wired to a Kubernetes probe: this is where +/// an operator looks to tell "the pod is fine, Postgres is not" apart from "the +/// pod is broken". It is the only endpoint that touches the shared pools. async fn status_handler(State(state): State>) -> impl IntoResponse { - Json(status_payload(state.started_at.elapsed().as_secs())) + let report = state + .dependency_diagnostics + .evaluate(&state.db, &state.redis_pool) + .await; + let mut payload = status_payload(state.started_at.elapsed().as_secs()); + payload["dependencies"] = dependency_diagnostics_payload(&report); + Json(payload) } /// `/_mesh` — live mesh status: peer table, connection/phi state, per-peer @@ -761,7 +769,6 @@ fn build_cors_layer(cors_origins: &[String]) -> CorsLayer { #[cfg(test)] mod tests { use std::collections::VecDeque; - use std::sync::atomic::{AtomicUsize, Ordering as AtomicOrdering}; use std::sync::{Mutex, PoisonError}; use std::time::Duration; @@ -770,7 +777,7 @@ mod tests { use opentelemetry::trace::TracerProvider as _; use opentelemetry_sdk::trace::{InMemorySpanExporter, SdkTracerProvider}; use tokio::net::TcpListener; - use tokio::sync::{mpsc, Notify}; + use tokio::sync::mpsc; use tokio_tungstenite::{connect_async, tungstenite::Message}; use tower::ServiceBuilder; use tracing::Instrument as _; @@ -778,18 +785,18 @@ mod tests { use super::*; - struct ScriptedReadinessEvaluator { - evaluations: Mutex>, + struct ScriptedDependencyEvaluator { + evaluations: Mutex>, } - impl ScriptedReadinessEvaluator { - fn new(evaluations: impl IntoIterator) -> Self { + impl ScriptedDependencyEvaluator { + fn new(evaluations: impl IntoIterator) -> Self { Self { evaluations: Mutex::new(evaluations.into_iter().collect()), } } - fn push(&self, evaluation: ReadinessEvaluation) { + fn push(&self, evaluation: DependencyReport) { self.evaluations .lock() .unwrap_or_else(PoisonError::into_inner) @@ -798,63 +805,26 @@ mod tests { } #[async_trait::async_trait] - impl readiness::ReadinessEvaluator for ScriptedReadinessEvaluator { + impl readiness::DependencyEvaluator for ScriptedDependencyEvaluator { async fn evaluate( &self, _db: &buzz_db::Db, _redis_pool: &deadpool_redis::Pool, - ) -> ReadinessEvaluation { + ) -> DependencyReport { self.evaluations .lock() .unwrap_or_else(PoisonError::into_inner) .pop_front() - .expect("scripted readiness evaluation") + .expect("scripted dependency report") } } - struct BarrierReadinessEvaluator { - calls: AtomicUsize, - first_started: Notify, - release_first: Notify, - first: ReadinessEvaluation, - second: ReadinessEvaluation, - } - - impl BarrierReadinessEvaluator { - fn new(first: ReadinessEvaluation, second: ReadinessEvaluation) -> Self { - Self { - calls: AtomicUsize::new(0), - first_started: Notify::new(), - release_first: Notify::new(), - first, - second, - } - } - } - - #[async_trait::async_trait] - impl readiness::ReadinessEvaluator for BarrierReadinessEvaluator { - async fn evaluate( - &self, - _db: &buzz_db::Db, - _redis_pool: &deadpool_redis::Pool, - ) -> ReadinessEvaluation { - if self.calls.fetch_add(1, AtomicOrdering::SeqCst) == 0 { - self.first_started.notify_waiters(); - self.release_first.notified().await; - self.first - } else { - self.second - } - } - } - - fn readiness_evaluation( + fn dependency_report( postgres: readiness::PostgresOutcome, redis: readiness::RedisOutcome, deletion_catalog: readiness::DeletionCatalogOutcome, - ) -> ReadinessEvaluation { - ReadinessEvaluation::from_results( + ) -> DependencyReport { + DependencyReport::from_results( readiness::TimedOutcome::new(postgres, Duration::from_millis(35)), readiness::TimedOutcome::new(redis, Duration::from_millis(20)), readiness::TimedOutcome::new(deletion_catalog, Duration::from_millis(15)), @@ -862,8 +832,8 @@ mod tests { ) } - fn ready_evaluation() -> ReadinessEvaluation { - readiness_evaluation( + fn ready_report() -> DependencyReport { + dependency_report( readiness::PostgresOutcome::Success, readiness::RedisOutcome::Success, readiness::DeletionCatalogOutcome::Success, @@ -945,10 +915,19 @@ mod tests { Arc::new(state) } - async fn readiness_state(evaluator: Arc) -> Arc { + async fn readiness_state(evaluator: Arc) -> Arc { + let mut state = unreachable_dependency_state().await; + Arc::get_mut(&mut state) + .expect("sole reference") + .set_dependency_evaluator(evaluator); + state + } + + /// A relay process whose shared Postgres and Redis are both unroutable. + async fn unreachable_dependency_state() -> Arc { let mut config = crate::config::Config::from_env().expect("default config loads"); config.require_relay_membership = false; - config.database_url = "postgres://buzz:buzz_dev@127.0.0.1:1/buzz".to_string(); + config.database_url = "postgres://buzz:buzz_dev@127.0.0.1:1/buzz".to_string(); // sadscan:disable np.postgres.1 -- local test-only credentials on a closed port config.redis_url = "redis://127.0.0.1:1".to_string(); let pool = sqlx::PgPool::connect_lazy(&config.database_url).expect("lazy pg pool"); let db = buzz_db::Db::from_pool(pool.clone()); @@ -968,7 +947,7 @@ mod tests { buzz_workflow::WorkflowConfig::default(), )); let media_storage = buzz_media::MediaStorage::new(&config.media).expect("media storage"); - let (mut state, _audit_shutdown) = AppState::new( + let (state, _audit_shutdown) = AppState::new( config, db, redis_pool, @@ -980,7 +959,6 @@ mod tests { nostr::Keys::generate(), media_storage, ); - state.set_readiness_evaluator(evaluator); Arc::new(state) } @@ -1001,6 +979,86 @@ mod tests { (status, payload) } + async fn status_request(router: Router) -> (StatusCode, serde_json::Value) { + let response = router + .oneshot( + Request::get("/_status") + .body(Body::empty()) + .expect("status request"), + ) + .await + .expect("status response"); + let status = response.status(); + let body = axum::body::to_bytes(response.into_body(), 64 * 1024) + .await + .expect("status response body"); + let payload = serde_json::from_slice(&body).expect("status JSON"); + (status, payload) + } + + /// The incident regression. Shared Postgres and Redis pressure took every + /// replica out of the load balancer at once, so a reconnect burst had + /// nowhere to land. Readiness answers for this process only: a pod whose + /// shared dependencies are unreachable is still a healthy pod, and only a + /// local shutdown may withdraw it. + #[tokio::test] + async fn readiness_answers_from_local_lifecycle_not_shared_dependencies() { + let state = unreachable_dependency_state().await; + + for router in [ + build_health_router(state.clone()), + build_router(state.clone()), + ] { + assert_eq!( + readiness_request(router).await, + (StatusCode::OK, json!({"status": "ready"})), + "unreachable shared dependencies must not deroute a healthy pod" + ); + } + + state.begin_shutdown(); + + for router in [ + build_health_router(state.clone()), + build_router(state.clone()), + ] { + assert_eq!( + readiness_request(router).await, + ( + StatusCode::SERVICE_UNAVAILABLE, + json!({"status": "shutting_down"}) + ), + "a draining pod must still withdraw itself" + ); + } + } + + /// Dependency health did not disappear with the probe — it moved to the + /// diagnostic endpoint, which is never wired to a Kubernetes probe. + #[tokio::test] + async fn status_retains_dependency_diagnostics_off_the_probe_path() { + let evaluator = Arc::new(ScriptedDependencyEvaluator::new([dependency_report( + readiness::PostgresOutcome::Success, + readiness::RedisOutcome::PoolTimeout, + readiness::DeletionCatalogOutcome::Success, + )])); + let state = readiness_state(evaluator).await; + + let (status, payload) = status_request(build_health_router(state)).await; + + assert_eq!(status, StatusCode::OK); + assert_eq!(payload["service"], "buzz-relay"); + assert_eq!( + payload["dependencies"], + json!({ + "postgres": true, + "redis": false, + "deletion_catalog": true, + "reason": "redis_pool_timeout" + }) + ); + } + fn readiness_metric_lines(rendered: &str) -> Vec<&str> { rendered .lines() @@ -1008,15 +1066,6 @@ mod tests { .collect() } - fn sorted_readiness_metric_lines(rendered: &str) -> Vec { - let mut lines = readiness_metric_lines(rendered) - .into_iter() - .map(str::to_owned) - .collect::>(); - lines.sort(); - lines - } - fn metric_value(rendered: &str, exact_prefix: &str) -> f64 { rendered .lines() @@ -1028,16 +1077,22 @@ mod tests { .unwrap_or_else(|| panic!("missing metric line: {exact_prefix}")) } + /// The frozen telemetry contract for the health listener. + /// + /// Readiness is lifecycle-only: its counter carries exactly two reasons and + /// its gauge follows shutdown, never a dependency. Dependency families are + /// still exported, but only by the diagnostic `/_status` endpoint, and + /// public-listener traffic moves nothing. #[test] - fn production_readiness_routes_export_the_frozen_health_only_contract() { + fn production_health_routes_export_the_frozen_telemetry_contract() { let runtime = tokio::runtime::Builder::new_current_thread() .enable_all() .build() .expect("current-thread runtime"); - let evaluator = Arc::new(ScriptedReadinessEvaluator::new(std::iter::repeat_n( - ready_evaluation(), - 4, - ))); + // Seeded with the first `/_status` evaluation only; the coverage loop + // below pushes the rest, one per request, so the evaluator never + // serves a report the assertions did not choose. + let evaluator = Arc::new(ScriptedDependencyEvaluator::new([ready_report()])); let (recorder, handle) = crate::metrics::readiness_test_recorder(); metrics::with_local_recorder(&recorder, || { @@ -1062,138 +1117,117 @@ mod tests { readiness_request(health.clone()).await, (StatusCode::OK, json!({"status": "ready"})) ); - let first_scrape = handle.render(); - - assert!(first_scrape.contains("# TYPE buzz_readiness_checks_total counter")); - assert!(first_scrape - .contains("# TYPE buzz_readiness_dependency_checks_total counter")); - assert!(first_scrape - .contains("# TYPE buzz_readiness_check_duration_seconds histogram")); - assert!(first_scrape.contains("# TYPE buzz_readiness_state gauge")); + let after_probe = handle.render(); + + assert!(after_probe.contains("# TYPE buzz_readiness_checks_total counter")); + assert!(after_probe.contains("# TYPE buzz_readiness_state gauge")); assert_eq!( - metric_value( - &first_scrape, - "buzz_readiness_checks_total{reason=\"ready\"}" - ), + metric_value(&after_probe, "buzz_readiness_checks_total{reason=\"ready\"}"), 1.0 ); assert_eq!( - metric_value( - &first_scrape, - "buzz_readiness_dependency_checks_total{dependency=\"postgres\",outcome=\"success\"}" - ), + metric_value(&after_probe, "buzz_readiness_state{check=\"overall\"}"), 1.0 ); + assert!( + !after_probe.contains("buzz_readiness_dependency_checks_total{"), + "the probe must not touch a shared dependency" + ); + assert!( + !after_probe.contains("buzz_readiness_check_duration_seconds_count"), + "the probe must not record a dependency latency sample" + ); + + // Dependency telemetry now belongs to the diagnostic endpoint. + let (status, payload) = status_request(health.clone()).await; + assert_eq!(status, StatusCode::OK); + assert_eq!(payload["dependencies"]["reason"], json!("ready")); + let after_status = handle.render(); + assert!( + after_status.contains("# TYPE buzz_readiness_dependency_checks_total counter") + ); + assert!( + after_status.contains("# TYPE buzz_readiness_check_duration_seconds histogram") + ); assert_eq!( metric_value( - &first_scrape, - "buzz_readiness_state{check=\"overall\"}" + &after_status, + "buzz_readiness_dependency_checks_total{dependency=\"postgres\",outcome=\"success\"}" ), 1.0 ); for bucket in ["2", "2.5", "+Inf"] { - assert!(first_scrape.contains(&format!( + assert!(after_status.contains(&format!( "buzz_readiness_check_duration_seconds_bucket{{check=\"overall\",le=\"{bucket}\"}}" ))); } - assert!(!first_scrape.contains("result=")); - assert!(!first_scrape + assert!(!after_status.contains("result=")); + assert!(!after_status .lines() .filter(|line| line.starts_with("buzz_readiness_check_duration_seconds")) .any(|line| line.contains("outcome="))); + for dependency in ["postgres", "redis", "deletion_catalog"] { + assert!( + !after_status + .contains(&format!("buzz_readiness_state{{check=\"{dependency}\"}}")), + "dependency health has no publishable readiness gauge" + ); + } - let before_public_failure = sorted_readiness_metric_lines(&first_scrape); - evaluator.push(readiness_evaluation( - readiness::PostgresOutcome::Success, - readiness::RedisOutcome::PoolTimeout, - readiness::DeletionCatalogOutcome::Success, - )); - assert_eq!( - readiness_request(public.clone()).await, + // A failing dependency is reported and changes nothing about + // whether this pod stays in the load balancer. This set also + // covers every valid dependency/outcome pair, so the series + // total below is exact rather than merely bounded. + let coverage = [ ( - StatusCode::SERVICE_UNAVAILABLE, - json!({ - "status": "not_ready", - "postgres": true, - "redis": false, - "deletion_catalog": true - }) - ) - ); - assert_eq!( - sorted_readiness_metric_lines(&handle.render()), - before_public_failure - ); - - let contract_evaluations = [ - readiness_evaluation( readiness::PostgresOutcome::PoolTimeout, - readiness::RedisOutcome::Success, - readiness::DeletionCatalogOutcome::Success, + readiness::RedisOutcome::PoolTimeout, + readiness::DeletionCatalogOutcome::OperationTimeout, ), - readiness_evaluation( + ( readiness::PostgresOutcome::PoolError, - readiness::RedisOutcome::Success, - readiness::DeletionCatalogOutcome::Success, + readiness::RedisOutcome::PoolError, + readiness::DeletionCatalogOutcome::OperationError, ), - readiness_evaluation( + ( readiness::PostgresOutcome::QueryTimeout, readiness::RedisOutcome::Success, readiness::DeletionCatalogOutcome::Success, ), - readiness_evaluation( + ( readiness::PostgresOutcome::QueryError, readiness::RedisOutcome::Success, readiness::DeletionCatalogOutcome::Success, ), - readiness_evaluation( - readiness::PostgresOutcome::Success, - readiness::RedisOutcome::PoolTimeout, - readiness::DeletionCatalogOutcome::Success, - ), - readiness_evaluation( - readiness::PostgresOutcome::Success, - readiness::RedisOutcome::PoolError, - readiness::DeletionCatalogOutcome::Success, - ), - readiness_evaluation( - readiness::PostgresOutcome::Success, - readiness::RedisOutcome::Success, - readiness::DeletionCatalogOutcome::OperationTimeout, - ), - readiness_evaluation( - readiness::PostgresOutcome::Success, - readiness::RedisOutcome::Success, - readiness::DeletionCatalogOutcome::OperationError, - ), - readiness_evaluation( - readiness::PostgresOutcome::PoolTimeout, - readiness::RedisOutcome::PoolTimeout, - readiness::DeletionCatalogOutcome::OperationTimeout, - ), - readiness_evaluation( - readiness::PostgresOutcome::PoolError, - readiness::RedisOutcome::PoolError, - readiness::DeletionCatalogOutcome::Success, - ), ]; - for evaluation in contract_evaluations { - evaluator.push(evaluation); - let (status, payload) = readiness_request(health.clone()).await; - assert_eq!(status, StatusCode::SERVICE_UNAVAILABLE); - assert_eq!(payload["reason"], json!(evaluation.reason.label())); + for (index, (postgres, redis, deletion_catalog)) in + coverage.into_iter().enumerate() + { + evaluator.push(dependency_report(postgres, redis, deletion_catalog)); + let (status, degraded) = status_request(health.clone()).await; + assert_eq!(status, StatusCode::OK); + if index == 0 { + assert_eq!( + degraded["dependencies"], + json!({ + "postgres": false, + "redis": false, + "deletion_catalog": false, + "reason": "overall_timeout" + }) + ); + } + assert_eq!( + readiness_request(health.clone()).await, + (StatusCode::OK, json!({"status": "ready"})), + "a failing dependency must never deroute this pod" + ); } - let before_shutdown = handle.render(); - let histogram_counts_before = ["overall", "postgres", "redis", "deletion_catalog"] - .map(|check| { - metric_value( - &before_shutdown, - &format!( - "buzz_readiness_check_duration_seconds_count{{check=\"{check}\"}}" - ), - ) - }); + let histogram_count_before = metric_value( + &handle.render(), + "buzz_readiness_check_duration_seconds_count{check=\"overall\"}", + ); state.begin_shutdown(); assert_eq!( readiness_request(public).await, @@ -1202,8 +1236,8 @@ mod tests { json!({"status": "shutting_down"}) ) ); - let after_public_shutdown = handle.render(); - assert!(after_public_shutdown + assert!(handle + .render() .lines() .all(|line| !line.contains("reason=\"shutting_down\""))); @@ -1215,28 +1249,23 @@ mod tests { ) ); let final_scrape = handle.render(); - let histogram_counts_after = ["overall", "postgres", "redis", "deletion_catalog"] - .map(|check| { - metric_value( - &final_scrape, - &format!( - "buzz_readiness_check_duration_seconds_count{{check=\"{check}\"}}" - ), - ) - }); - assert_eq!(histogram_counts_after, histogram_counts_before); assert_eq!( metric_value( &final_scrape, - "buzz_readiness_checks_total{reason=\"shutting_down\"}" + "buzz_readiness_check_duration_seconds_count{check=\"overall\"}" ), - 1.0 + histogram_count_before, + "shutdown must not fabricate a dependency latency sample" ); assert_eq!( metric_value( &final_scrape, - "buzz_readiness_state{check=\"overall\"}" + "buzz_readiness_checks_total{reason=\"shutting_down\"}" ), + 1.0 + ); + assert_eq!( + metric_value(&final_scrape, "buzz_readiness_state{check=\"overall\"}"), 0.0 ); assert!(!final_scrape.contains("sensitive-sql-or-url")); @@ -1249,138 +1278,7 @@ mod tests { assert_eq!( readiness_metric_lines(&final_scrape).len(), readiness::READINESS_RAW_SERIES_PER_POD, - "readiness series contract must stay at or below its 99-series cap" - ); - }); - }); - } - - fn run_out_of_order_route_case( - first: ReadinessEvaluation, - second: ReadinessEvaluation, - ) -> (serde_json::Value, serde_json::Value, String) { - let runtime = tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime"); - let evaluator = Arc::new(BarrierReadinessEvaluator::new(first, second)); - let (recorder, handle) = crate::metrics::readiness_test_recorder(); - - metrics::with_local_recorder(&recorder, || { - runtime.block_on(async { - let state = readiness_state(evaluator.clone()).await; - let health = build_health_router(state); - let first_started = evaluator.first_started.notified(); - let slow_first = tokio::spawn(readiness_request(health.clone())); - first_started.await; - - let (_, second_payload) = readiness_request(health).await; - evaluator.release_first.notify_one(); - let (_, first_payload) = slow_first.await.expect("slow first probe task"); - (first_payload, second_payload, handle.render()) - }) - }) - } - - #[test] - fn real_health_route_generation_fence_covers_both_completion_orders() { - let failure = readiness_evaluation( - readiness::PostgresOutcome::Success, - readiness::RedisOutcome::PoolTimeout, - readiness::DeletionCatalogOutcome::Success, - ); - - let (older_failure, newer_success, success_scrape) = - run_out_of_order_route_case(failure, ready_evaluation()); - assert_eq!(older_failure["reason"], json!("redis_pool_timeout")); - assert_eq!(newer_success, json!({"status": "ready"})); - assert_eq!( - metric_value(&success_scrape, "buzz_readiness_state{check=\"overall\"}"), - 1.0 - ); - assert_eq!( - metric_value(&success_scrape, "buzz_readiness_state{check=\"redis\"}"), - 1.0 - ); - - let (older_success, newer_failure, failure_scrape) = - run_out_of_order_route_case(ready_evaluation(), failure); - assert_eq!(older_success, json!({"status": "ready"})); - assert_eq!(newer_failure["reason"], json!("redis_pool_timeout")); - assert_eq!( - metric_value(&failure_scrape, "buzz_readiness_state{check=\"overall\"}"), - 0.0 - ); - assert_eq!( - metric_value(&failure_scrape, "buzz_readiness_state{check=\"redis\"}"), - 0.0 - ); - for scrape in [&success_scrape, &failure_scrape] { - assert_eq!( - metric_value(scrape, "buzz_readiness_checks_total{reason=\"ready\"}"), - 1.0 - ); - assert_eq!( - metric_value( - scrape, - "buzz_readiness_checks_total{reason=\"redis_pool_timeout\"}" - ), - 1.0 - ); - } - } - - #[test] - fn real_health_route_shutdown_fence_dominates_an_in_flight_success() { - let runtime = tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime"); - let evaluator = Arc::new(BarrierReadinessEvaluator::new( - ready_evaluation(), - ready_evaluation(), - )); - let (recorder, handle) = crate::metrics::readiness_test_recorder(); - - metrics::with_local_recorder(&recorder, || { - runtime.block_on(async { - let state = readiness_state(evaluator.clone()).await; - let health = build_health_router(state.clone()); - let first_started = evaluator.first_started.notified(); - let in_flight = tokio::spawn(readiness_request(health)); - first_started.await; - - state.begin_shutdown(); - evaluator.release_first.notify_one(); - assert_eq!( - in_flight.await.expect("in-flight readiness task"), - ( - StatusCode::SERVICE_UNAVAILABLE, - json!({"status": "shutting_down"}) - ) - ); - - let scrape = handle.render(); - assert_eq!( - metric_value(&scrape, "buzz_readiness_state{check=\"overall\"}"), - 0.0 - ); - assert!(scrape - .lines() - .all(|line| !line.starts_with("buzz_readiness_state{check=\"postgres\"}"))); - assert_eq!( - metric_value( - &scrape, - "buzz_readiness_checks_total{reason=\"shutting_down\"}" - ), - 1.0 - ); - assert_eq!( - metric_value( - &scrape, - "buzz_readiness_dependency_checks_total{dependency=\"postgres\",outcome=\"success\"}" - ), - 1.0 + "readiness series contract must stay at or below its 86-series cap" ); }); }); diff --git a/crates/buzz-relay/src/state.rs b/crates/buzz-relay/src/state.rs index 72376402001..6a4a70b9d6b 100644 --- a/crates/buzz-relay/src/state.rs +++ b/crates/buzz-relay/src/state.rs @@ -182,10 +182,86 @@ impl Drop for CommunityConnectionGuard { } } +/// Message reported when the one-time Redis bootstrap gate rejects startup. +/// +/// Bounded and stable so operators and the boot regression test can match on +/// it without parsing the underlying driver error. +pub const REDIS_BOOTSTRAP_FAILURE: &str = "Redis command path unavailable at startup"; + +/// Budget for the one-time bootstrap PING. A refused port answers immediately; +/// this only bounds a blackholed address, where hanging forever would be worse +/// than exiting. +const REDIS_BOOTSTRAP_TIMEOUT: std::time::Duration = std::time::Duration::from_secs(5); + +/// Proves once, during startup, that the Redis command path this pod will serve +/// from can actually be reached. +/// +/// `deadpool_redis` pools dial lazily and `PubSubManager::new` only allocates +/// channels, so without this nothing in boot ever opened a command connection: +/// a relay came up against a dead Redis, bound its health listener, and — since +/// readiness reports local lifecycle only — advertised ready forever. Binding +/// that listener is a one-way latch, so the check has to happen before it, and +/// it is deliberately a *startup* gate: once serving, a Redis blip is a +/// dependency failure and must never change readiness. +pub async fn verify_redis_command_path(pool: &deadpool_redis::Pool) -> anyhow::Result<()> { + let ping = async { + let mut connection = pool + .get() + .await + .map_err(|error| anyhow::anyhow!("{REDIS_BOOTSTRAP_FAILURE}: {error}"))?; + redis::cmd("PING") + .query_async::(&mut connection) + .await + .map_err(|error| anyhow::anyhow!("{REDIS_BOOTSTRAP_FAILURE}: {error}")) + }; + + match tokio::time::timeout(REDIS_BOOTSTRAP_TIMEOUT, ping).await { + Err(_) => Err(anyhow::anyhow!( + "{REDIS_BOOTSTRAP_FAILURE}: no response within {REDIS_BOOTSTRAP_TIMEOUT:?}" + )), + Ok(result) => result.map(|_| ()), + } +} + +/// Bounded outcome of the durable community-active check run when a socket is +/// admitted. +/// +/// `outcome` is the only dimension. Community, tenant, connection, and error +/// text are request-controlled and deliberately absent from the label set. +#[derive(Debug, Clone, Copy)] +enum AdmissionOutcome { + Active, + Inactive, + CheckError, +} + +impl AdmissionOutcome { + fn label(self) -> &'static str { + match self { + Self::Active => "active", + Self::Inactive => "inactive", + Self::CheckError => "check_error", + } + } +} + +fn record_admission_check(outcome: AdmissionOutcome) { + metrics::counter!( + "buzz_community_admission_checks_total", + "outcome" => outcome.label(), + ) + .increment(1); +} + /// Registers a socket, durably revalidates its community, then runs it. /// /// The ordering is the archival admission invariant: archive-before-query is /// observed by the query, while archive-after-registration sees the token. +/// +/// Only a confirmed `Ok(false)` cancels. A lookup `Err` admits the socket and +/// defers to [`AppState::revalidate_live_communities`], because a database blip +/// is not evidence of archival and dropping sockets on one amplifies the very +/// pressure that caused it. pub(crate) async fn run_registered_community_connection( registry: &CommunityConnectionRegistry, connection_id: Uuid, @@ -201,9 +277,28 @@ pub(crate) async fn run_registered_community_connection record_admission_check(AdmissionOutcome::Active), + Ok(false) => { + record_admission_check(AdmissionOutcome::Inactive); + cancel.cancel(); + return; + } + Err(error) => { + // A lookup failure is not an answer, and dropping the socket on one + // turns shared database pressure into a reconnect storm that feeds + // straight back into the exhausted pool. Admitting costs nothing + // durable: writes still fail closed on their own per-event fence + // (`handlers::ingest::map_serving_fence_state`), and + // `AppState::revalidate_live_communities` closes the socket on the + // next tick if the community really is inactive. + record_admission_check(AdmissionOutcome::CheckError); + tracing::warn!( + %community_id, + %error, + "community active check failed; admitting the socket pending lifecycle revalidation" + ); + } } if cancel.is_cancelled() { return; @@ -719,8 +814,9 @@ pub struct AppState { pub audio_rooms: Arc, /// Set to `true` on SIGTERM — readiness probe returns 503. pub shutting_down: Arc, - /// Orders readiness gauge publication against terminal shutdown. - pub(crate) readiness: Arc, + /// Shared-dependency evaluation behind the diagnostic `/_status` endpoint. + /// Never consulted by a Kubernetes probe. + pub(crate) dependency_diagnostics: Arc, /// Process start time — used by `/_status` endpoint. pub started_at: Instant, /// Shared, community-scoped NIP-98 replay prevention. @@ -946,7 +1042,7 @@ impl AppState { git_pack_cache, audio_rooms: Arc::new(AudioRoomManager::new()), shutting_down: Arc::new(AtomicBool::new(false)), - readiness: Arc::new(crate::readiness::ReadinessCoordinator::default()), + dependency_diagnostics: Arc::new(crate::readiness::DependencyDiagnostics::default()), started_at: Instant::now(), nip98_replay, gif_http_client, @@ -990,21 +1086,22 @@ impl AppState { ) } - /// Atomically closes readiness publication before exposing shutdown to - /// the relay's other fast-path lifecycle checks. + /// Withdraws this pod from routing. The lifecycle flag is authoritative for + /// `/_readiness`; the gauge is published immediately so a draining pod does + /// not report ready until its next probe. pub fn begin_shutdown(&self) { - self.readiness.begin_shutdown(); self.shutting_down.store(true, Ordering::Release); + crate::readiness::record_overall_state(false); } #[cfg(test)] - pub(crate) fn set_readiness_evaluator( + pub(crate) fn set_dependency_evaluator( &mut self, - evaluator: Arc, + evaluator: Arc, ) { - self.readiness = Arc::new(crate::readiness::ReadinessCoordinator::with_evaluator( - evaluator, - )); + self.dependency_diagnostics = Arc::new( + crate::readiness::DependencyDiagnostics::with_evaluator(evaluator), + ); } /// Inter-relay mesh handle. `None` ⇒ mesh-off / single-instance: callers @@ -2096,6 +2193,136 @@ pub(crate) mod tests { assert!(!started_during.load(Ordering::SeqCst)); } + /// Reads one `buzz_community_admission_checks_total` series by exact label set. + fn admission_counter( + snapshot: &[( + metrics_util::CompositeKey, + Option, + Option, + metrics_util::debugging::DebugValue, + )], + outcome: &str, + ) -> Option { + snapshot.iter().find_map(|(key, _, _, value)| { + let labels = key + .key() + .labels() + .map(|label| (label.key(), label.value())) + .collect::>(); + if key.key().name() != "buzz_community_admission_checks_total" + || labels != [("outcome", outcome)] + { + return None; + } + match value { + metrics_util::debugging::DebugValue::Counter(count) => Some(*count), + _ => panic!("community admission checks must be a counter"), + } + }) + } + + /// The reconnect-amplification regression. A durable *answer* of "inactive" + /// cancels the socket, but a lookup *failure* is not an answer: the socket is + /// admitted and the periodic revalidation backstop owns eviction. Collapsing + /// both into "not active" turned shared database pressure into a reconnect + /// storm that fed straight back into the exhausted pool. + #[test] + fn confirmed_inactive_cancels_while_an_active_check_error_admits_the_socket() { + let runtime = tokio::runtime::Builder::new_current_thread() + .enable_all() + .build() + .expect("current-thread runtime"); + let recorder = metrics_util::debugging::DebuggingRecorder::new(); + let snapshotter = recorder.snapshotter(); + + let (inactive_cancel, inactive_started, error_started, active_started) = + metrics::with_local_recorder(&recorder, || { + runtime.block_on(async { + let registry = CommunityConnectionRegistry::new(); + let community = CommunityId::from_uuid(Uuid::from_u128(0xa)); + + let inactive_cancel = CancellationToken::new(); + let inactive_started = Arc::new(AtomicBool::new(false)); + let started = Arc::clone(&inactive_started); + run_registered_community_connection( + ®istry, + Uuid::new_v4(), + community, + CommunityConnectionControl::new(inactive_cancel.clone()), + || async { Ok(false) }, + move |_| async move { started.store(true, Ordering::SeqCst) }, + ) + .await; + + let error_started = Arc::new(AtomicBool::new(false)); + let started = Arc::clone(&error_started); + run_registered_community_connection( + ®istry, + Uuid::new_v4(), + community, + CommunityConnectionControl::new(CancellationToken::new()), + || async { Err(buzz_db::DbError::Sqlx(sqlx::Error::PoolTimedOut)) }, + move |_| async move { started.store(true, Ordering::SeqCst) }, + ) + .await; + + let active_started = Arc::new(AtomicBool::new(false)); + let started = Arc::clone(&active_started); + run_registered_community_connection( + ®istry, + Uuid::new_v4(), + community, + CommunityConnectionControl::new(CancellationToken::new()), + || async { Ok(true) }, + move |_| async move { started.store(true, Ordering::SeqCst) }, + ) + .await; + + ( + inactive_cancel, + inactive_started, + error_started, + active_started, + ) + }) + }); + + assert!( + inactive_cancel.is_cancelled(), + "a confirmed-inactive community must still cancel its socket" + ); + assert!( + !inactive_started.load(Ordering::SeqCst), + "a confirmed-inactive community must never start the socket body" + ); + assert!( + error_started.load(Ordering::SeqCst), + "an active-check error must admit the socket and leave eviction to revalidation" + ); + assert!(active_started.load(Ordering::SeqCst)); + + let snapshot = snapshotter.snapshot().into_vec(); + assert_eq!(admission_counter(&snapshot, "inactive"), Some(1)); + assert_eq!(admission_counter(&snapshot, "check_error"), Some(1)); + assert_eq!(admission_counter(&snapshot, "active"), Some(1)); + + let label_sets = snapshot + .iter() + .filter(|(key, _, _, _)| key.key().name() == "buzz_community_admission_checks_total") + .map(|(key, _, _, _)| { + key.key() + .labels() + .map(|label| label.key().to_owned()) + .collect::>() + }) + .collect::>(); + assert_eq!(label_sets.len(), 3, "outcome is the only dimension"); + assert!( + label_sets.iter().all(|labels| labels == &["outcome"]), + "admission telemetry must never carry community, tenant, or error labels: {label_sets:?}" + ); + } + #[tokio::test] async fn revalidation_continues_after_one_community_lookup_failure() { let registry = CommunityConnectionRegistry::new(); diff --git a/crates/buzz-relay/tests/boot_lifecycle.rs b/crates/buzz-relay/tests/boot_lifecycle.rs index 17762bbdeab..cb4a062fafe 100644 --- a/crates/buzz-relay/tests/boot_lifecycle.rs +++ b/crates/buzz-relay/tests/boot_lifecycle.rs @@ -10,6 +10,7 @@ use std::{ use serde_json::Value; use buzz_relay::lifecycle::StartupPhase; +use buzz_relay::state::REDIS_BOOTSTRAP_FAILURE; const VALID_RELAY_PRIVATE_KEY: &str = "0000000000000000000000000000000000000000000000000000000000000001"; @@ -500,3 +501,91 @@ fn successful_main_emits_complete_lifecycle_without_startup_metrics() { assert_terminal(&events, "metrics_bind", "succeeded", None); assert_terminal(&events, "process_telemetry", "succeeded", None); } + +/// Boot gates that need a live Postgres to reach the code under test. Named +/// `postgres_tests` so `.config/nextest.toml`'s `postgres-ci` default filter +/// discovers them structurally; the wrapper hands each test its own database +/// through `DATABASE_URL`. +mod postgres_tests { + use super::*; + + fn reserve_closed_port() -> u16 { + let reserved = TcpListener::bind(("127.0.0.1", 0)).expect("reserve port"); + let port = reserved.local_addr().expect("reserved address").port(); + drop(reserved); + port + } + + /// Runs the relay until it exits on its own, or kills it once `timeout` + /// passes. Unlike `run_relay`, a relay that keeps serving is a result to + /// assert on rather than a panic, which is the whole point here. + fn run_until_exit(environment: &[(&str, &str)], timeout: Duration) -> (bool, Output) { + let mut process = RelayProcess::spawn(environment); + let deadline = Instant::now() + timeout; + while Instant::now() < deadline { + if process.try_wait().is_some() { + return (true, process.wait(Duration::from_secs(2))); + } + thread::sleep(Duration::from_millis(20)); + } + (false, process.terminate()) + } + + /// Redis is required for pub/sub fan-out, presence, and typing, but nothing + /// in boot ever opened a command connection: `deadpool_redis` pools dial + /// lazily and `PubSubManager::new` only allocates channels, so "Redis + /// pub/sub connected" was logged against a dead port. A relay could + /// therefore boot with Redis unreachable, bind its health listener, and — + /// now that readiness answers from local lifecycle alone — advertise ready + /// for the rest of its life. The bootstrap gate is the one-time proof that + /// the command path has connected at least once, and it has to land before + /// the listener binds, because binding is the one-way latch that makes this + /// pod routable. + /// + /// The git conformance probe is disabled so the only remaining startup-fatal + /// gate is the one under test. + #[test] + #[ignore = "requires PostgreSQL"] + fn unreachable_redis_fails_boot_before_the_health_listener_binds() { + let database_url = std::env::var("DATABASE_URL") + .expect("postgres lane provides DATABASE_URL for each test process"); + let redis_url = format!("redis://127.0.0.1:{}", reserve_closed_port()); + let metrics_port = reserve_closed_port().to_string(); + let health_port = reserve_closed_port(); + let health_port_value = health_port.to_string(); + + let (exited, output) = run_until_exit( + &[ + ("BUZZ_RELAY_PRIVATE_KEY", VALID_RELAY_PRIVATE_KEY), + ("BUZZ_METRICS_PORT", &metrics_port), + ("BUZZ_HEALTH_PORT", &health_port_value), + ("DATABASE_URL", &database_url), + ("REDIS_URL", &redis_url), + ("BUZZ_GIT_CONFORMANCE_PROBE", "false"), + ], + CHILD_TIMEOUT, + ); + let logs = format!( + "{}{}", + String::from_utf8_lossy(&output.stdout), + String::from_utf8_lossy(&output.stderr) + ); + + assert!( + !logs.contains("Health probe listener started"), + "the Redis bootstrap gate must run before the health listener binds: {logs}" + ); + assert!( + exited && !output.status.success(), + "an unreachable Redis command path must be startup-fatal: {logs}" + ); + assert!( + logs.contains(REDIS_BOOTSTRAP_FAILURE), + "the failure must name the gate that rejected boot: {logs}" + ); + assert!( + TcpListener::bind(("0.0.0.0", health_port)).is_ok(), + "the health port must never have been bound" + ); + } +} diff --git a/deploy/charts/buzz/README.md b/deploy/charts/buzz/README.md index a6b74e87572..5920432ffcf 100644 --- a/deploy/charts/buzz/README.md +++ b/deploy/charts/buzz/README.md @@ -110,10 +110,11 @@ SigV4 signing, so do not put the bucket into `s3.endpoint`; pass Railway's base Object storage is contacted during relay startup only when `BUZZ_GIT_CONFORMANCE_PROBE` is enabled (the relay default). A probe failure is -startup-fatal, so Kubernetes readiness never opens. If an operator explicitly -disables that probe through `relay.extraEnv`, `/_readiness` does not test object -storage; configuration is still parsed strictly, but reachability and addressing -errors surface on the first storage operation. +startup-fatal, so the process exits and Kubernetes readiness never opens. If an +operator explicitly disables that probe through `relay.extraEnv`, configuration +is still parsed strictly, but reachability and addressing errors surface on the +first storage operation. `/_readiness` tests no external dependency in either +case — see the readiness contract below. ### Early-startup telemetry contract @@ -125,26 +126,56 @@ These phases intentionally do not emit metrics. Most run before the Prometheus exporter exists, and one uniform log-only contract preserves every phase's real event time and failure without assigning an eventual scrape time to earlier work. +### Readiness contract + +**`/_readiness` reports local process lifecycle only.** It performs no +Postgres, Redis, or deletion-catalog I/O: `shutting_down` returns 503, and any +other state returns 200. Shared dependencies are shared by every replica, so +gating the probe on them removed the whole deployment from the load balancer at +once and left a reconnect burst with nowhere to land. There is no separate +"starting" state — the health listener does not bind until the database, +migrations, Redis, and pub/sub are up, so a process that can answer has booted. + +Shared-dependency health moved to **`/_status`** on the same private health +listener, under a `dependencies` object carrying the `postgres`, `redis`, +`deletion_catalog`, and aggregate `reason` fields the readiness body used to +return. Do not wire `/_status` to a Kubernetes probe; it is the only endpoint +that touches the shared pools. + ### Readiness telemetry contract Only requests served by the private health listener (`BUZZ_HEALTH_PORT`) emit -rollout readiness telemetry. The compatibility `/_readiness` route on the public -app listener returns health but does not change these metrics. +rollout telemetry. The compatibility `/_readiness` route on the public app +listener returns the same lifecycle answer but does not change these metrics. + +| Metric | Type | Labels | Source | +|--------|------|--------|--------| +| `buzz_readiness_checks_total` | counter | `reason` ∈ {`ready`, `shutting_down`} | `/_readiness` | +| `buzz_readiness_state` | gauge | `check="overall"`; 1 ready, 0 shutting down | `/_readiness`, shutdown | +| `buzz_readiness_dependency_checks_total` | counter | `dependency`, typed bounded `outcome` | `/_status` | +| `buzz_readiness_check_duration_seconds` | histogram | `check` only | `/_status` | + +The two dependency families keep their `buzz_readiness_*` names for dashboard +continuity; their trigger moved from the 5s probe to `/_status`, so they now +sample only when an operator or a scheduled scrape requests that endpoint. + +The schema has a ceiling of 86 raw Prometheus series per pod: 2 probe reasons, +11 valid dependency/outcome pairs, 72 histogram series, and 1 gauge. Do not add +pod, ReplicaSet, version, rollout, error text, SQL, URL, tenant, user, +community, pubkey, header, query, or other request-controlled labels. A +readiness probe records no dependency attempt or latency sample at all. + +### Community admission telemetry | Metric | Type | Labels | |--------|------|--------| -| `buzz_readiness_checks_total` | counter | `reason` from the closed readiness-reason set | -| `buzz_readiness_dependency_checks_total` | counter | `dependency`, typed bounded `outcome` | -| `buzz_readiness_check_duration_seconds` | histogram | `check` only | -| `buzz_readiness_state` | gauge | `check` only; latest publishable generation | - -The schema has a ceiling of 99 raw Prometheus series per pod: 12 overall -reasons, 11 valid dependency/outcome pairs, 72 histogram series, and 4 gauges. -Do not add pod, ReplicaSet, version, rollout, error text, SQL, URL, tenant, -user, community, pubkey, header, query, or other request-controlled labels. -Shutdown without dependency evaluation increments only -`buzz_readiness_checks_total{reason="shutting_down"}` and sets the overall -state to zero; it does not fabricate dependency failures or latency samples. +| `buzz_community_admission_checks_total` | counter | `outcome` ∈ {`active`, `inactive`, `check_error`} | + +Counts the durable community-active check run when a socket is admitted. +`inactive` is a confirmed answer and cancels the socket; `check_error` is a +lookup failure and admits it, leaving eviction to the periodic lifecycle +revalidator. `outcome` is the only dimension — community and error text are +request-controlled and must never become labels. ### Operation-aware database pool acquisition contract diff --git a/docs/deployment-identity.md b/docs/deployment-identity.md index 32d8c426e76..ad356eb534c 100644 --- a/docs/deployment-identity.md +++ b/docs/deployment-identity.md @@ -47,6 +47,12 @@ The relay health listener exposes intrinsic build identity at `/_status`: "source_sha": "<40-character-source-sha>", "id": "github-actions::", "url": "https://github.com/block/buzz/actions/runs//attempts/" + }, + "dependencies": { + "postgres": true, + "redis": true, + "deletion_catalog": true, + "reason": "ready" } } ``` @@ -54,6 +60,11 @@ The relay health listener exposes intrinsic build identity at `/_status`: Non-CI builds report stable `unknown` or `local` fallback values instead of claiming provenance they do not have. +`dependencies` is a diagnostic snapshot of shared-dependency health, evaluated +per request with a two-second budget. `/_readiness` does not consult it — see +[the readiness contract](../deploy/charts/buzz/README.md#readiness-contract) — +so this endpoint must never be wired to a Kubernetes probe. + ## Helm digest pinning Buzz chart `0.1.8` and newer accept an immutable image digest: From 54414ff72d6ee9e7c1f8e815c915273e4391788c Mon Sep 17 00:00:00 2001 From: tornquist Date: Fri, 4 Sep 2026 20:28:38 +0000 Subject: [PATCH 02/17] test(relay): cover Redis bootstrap timeout Signed-off-by: tornquist Co-authored-by: Codex Signed-off-by: tornquist --- crates/buzz-relay/src/state.rs | 12 +- crates/buzz-relay/tests/boot_lifecycle.rs | 175 ++++++++++++++++++++++ 2 files changed, 186 insertions(+), 1 deletion(-) diff --git a/crates/buzz-relay/src/state.rs b/crates/buzz-relay/src/state.rs index 6a4a70b9d6b..592dc2d9eb7 100644 --- a/crates/buzz-relay/src/state.rs +++ b/crates/buzz-relay/src/state.rs @@ -193,6 +193,11 @@ pub const REDIS_BOOTSTRAP_FAILURE: &str = "Redis command path unavailable at sta /// than exiting. const REDIS_BOOTSTRAP_TIMEOUT: std::time::Duration = std::time::Duration::from_secs(5); +/// Keep the Redis driver's per-command timeout outside the relay-owned startup +/// budget so [`REDIS_BOOTSTRAP_TIMEOUT`] remains the one authoritative bound. +const REDIS_BOOTSTRAP_DRIVER_TIMEOUT: std::time::Duration = + REDIS_BOOTSTRAP_TIMEOUT.saturating_mul(2); + /// Proves once, during startup, that the Redis command path this pod will serve /// from can actually be reached. /// @@ -205,10 +210,15 @@ const REDIS_BOOTSTRAP_TIMEOUT: std::time::Duration = std::time::Duration::from_s /// dependency failure and must never change readiness. pub async fn verify_redis_command_path(pool: &deadpool_redis::Pool) -> anyhow::Result<()> { let ping = async { - let mut connection = pool + let connection = pool .get() .await .map_err(|error| anyhow::anyhow!("{REDIS_BOOTSTRAP_FAILURE}: {error}"))?; + // This one-shot connection is removed from the pool so extending its + // driver timeout cannot leak into normal serving traffic. The relay's + // outer timeout below must bound both lazy checkout and PING. + let mut connection = deadpool_redis::Connection::take(connection); + connection.set_response_timeout(REDIS_BOOTSTRAP_DRIVER_TIMEOUT); redis::cmd("PING") .query_async::(&mut connection) .await diff --git a/crates/buzz-relay/tests/boot_lifecycle.rs b/crates/buzz-relay/tests/boot_lifecycle.rs index cb4a062fafe..10e2c2e4f54 100644 --- a/crates/buzz-relay/tests/boot_lifecycle.rs +++ b/crates/buzz-relay/tests/boot_lifecycle.rs @@ -3,6 +3,7 @@ use std::{ io::{Read as _, Write as _}, net::{TcpListener, TcpStream}, process::{Child, Command, ExitStatus, Output, Stdio}, + sync::mpsc, thread::{self, JoinHandle}, time::{Duration, Instant}, }; @@ -509,6 +510,123 @@ fn successful_main_emits_complete_lifecycle_without_startup_metrics() { mod postgres_tests { use super::*; + const REDIS_BOOTSTRAP_BUDGET: Duration = Duration::from_secs(5); + const REDIS_BOOTSTRAP_SCHEDULING_SLACK: Duration = Duration::from_secs(3); + + /// A TCP peer that completes Redis's metadata handshake, then reads and + /// holds PING without replying. This distinguishes a bounded checkout + + /// PING from a refused connection, which returns before the bootstrap + /// timeout is exercised. + struct HangingRedisPeer { + redis_url: String, + request_received: mpsc::Receiver>, + stop: mpsc::Sender<()>, + worker: Option>, + } + + impl HangingRedisPeer { + fn spawn() -> Self { + let listener = TcpListener::bind(("127.0.0.1", 0)).expect("bind fake Redis peer"); + listener + .set_nonblocking(true) + .expect("set fake Redis listener nonblocking"); + let port = listener.local_addr().expect("fake Redis address").port(); + let (request_tx, request_received) = mpsc::channel(); + let (stop, stop_rx) = mpsc::channel(); + let worker = thread::spawn(move || loop { + if stop_rx.try_recv().is_ok() { + return; + } + let (mut stream, _) = match listener.accept() { + Ok(accepted) => accepted, + Err(error) if error.kind() == std::io::ErrorKind::WouldBlock => { + thread::sleep(Duration::from_millis(10)); + continue; + } + Err(error) => panic!("accept fake Redis connection: {error}"), + }; + stream + .set_read_timeout(Some(Duration::from_millis(100))) + .expect("bound fake Redis read"); + let mut request = Vec::new(); + loop { + let mut chunk = [0_u8; 4096]; + match stream.read(&mut chunk) { + Ok(0) => return, + Ok(read) => { + request.extend_from_slice(&chunk[..read]); + assert!( + request.len() <= 4096, + "fake Redis peer received an oversized request" + ); + let setinfo_commands = request + .windows(b"SETINFO".len()) + .filter(|window| *window == b"SETINFO") + .count(); + if setinfo_commands >= 2 { + // redis-rs pipelines CLIENT SETINFO lib-name + // and lib-ver while establishing a connection. + // Complete that handshake so the relay reaches + // its explicit bootstrap PING, then hold it. + stream + .write_all(b"+OK\r\n+OK\r\n") + .expect("reply to Redis client handshake"); + request.clear(); + continue; + } + if request + .windows(b"PING".len()) + .any(|window| window == b"PING") + { + let _ = request_tx.send(request); + let _ = stop_rx.recv_timeout(CHILD_TIMEOUT); + return; + } + } + Err(error) + if matches!( + error.kind(), + std::io::ErrorKind::WouldBlock | std::io::ErrorKind::TimedOut + ) => + { + if stop_rx.try_recv().is_ok() { + return; + } + } + Err(error) => panic!("read fake Redis request: {error}"), + } + } + }); + Self { + redis_url: format!("redis://127.0.0.1:{port}"), + request_received, + stop, + worker: Some(worker), + } + } + + fn redis_url(&self) -> &str { + &self.redis_url + } + + fn assert_request_received(&self, logs: &str) { + let request = self + .request_received + .recv_timeout(Duration::from_secs(1)) + .unwrap_or_else(|_| panic!("relay must reach the fake Redis peer: {logs}")); + assert!(!request.is_empty(), "fake Redis peer read an empty request"); + } + } + + impl Drop for HangingRedisPeer { + fn drop(&mut self) { + let _ = self.stop.send(()); + if let Some(worker) = self.worker.take() { + worker.join().expect("fake Redis peer must not panic"); + } + } + } + fn reserve_closed_port() -> u16 { let reserved = TcpListener::bind(("127.0.0.1", 0)).expect("reserve port"); let port = reserved.local_addr().expect("reserved address").port(); @@ -588,4 +706,61 @@ mod postgres_tests { "the health port must never have been bound" ); } + + /// A peer that accepts the socket but withholds its Redis response exercises + /// the outer timeout around both lazy pool checkout and PING. Removing or + /// narrowing that timeout makes this test kill a still-running relay at the + /// deadline instead of observing a startup failure. + #[test] + #[ignore = "requires PostgreSQL"] + fn hanging_redis_peer_times_out_before_the_health_listener_binds() { + let database_url = std::env::var("DATABASE_URL") + .expect("postgres lane provides DATABASE_URL for each test process"); + let redis_peer = HangingRedisPeer::spawn(); + let metrics_port = reserve_closed_port().to_string(); + let health_port = reserve_closed_port(); + let health_port_value = health_port.to_string(); + let timeout = REDIS_BOOTSTRAP_BUDGET + REDIS_BOOTSTRAP_SCHEDULING_SLACK; + let started_at = Instant::now(); + + let (exited, output) = run_until_exit( + &[ + ("BUZZ_RELAY_PRIVATE_KEY", VALID_RELAY_PRIVATE_KEY), + ("BUZZ_METRICS_PORT", &metrics_port), + ("BUZZ_HEALTH_PORT", &health_port_value), + ("DATABASE_URL", &database_url), + ("REDIS_URL", redis_peer.redis_url()), + ("BUZZ_GIT_CONFORMANCE_PROBE", "false"), + ], + timeout, + ); + let elapsed = started_at.elapsed(); + let logs = format!( + "{}{}", + String::from_utf8_lossy(&output.stdout), + String::from_utf8_lossy(&output.stderr) + ); + redis_peer.assert_request_received(&logs); + + assert!( + elapsed >= REDIS_BOOTSTRAP_BUDGET, + "the fake peer must hold the request through the bootstrap budget: {elapsed:?}: {logs}" + ); + assert!( + exited && elapsed < timeout && !output.status.success(), + "the outer bootstrap timeout must terminate the relay within scheduling slack: {elapsed:?}: {logs}" + ); + assert!( + logs.contains(REDIS_BOOTSTRAP_FAILURE), + "the timeout must report the bounded Redis bootstrap failure: {logs}" + ); + assert!( + !logs.contains("Health probe listener started"), + "the health listener must not bind before Redis bootstrap succeeds: {logs}" + ); + assert!( + TcpListener::bind(("0.0.0.0", health_port)).is_ok(), + "the health port must never have been bound" + ); + } } From 5f06addd609e1d53b414aa560fbe39012e87c18d Mon Sep 17 00:00:00 2001 From: tornquist Date: Sat, 5 Sep 2026 13:28:03 +0000 Subject: [PATCH 03/17] Fix relay permissions in PostgreSQL CI Signed-off-by: tornquist Co-authored-by: Codex Signed-off-by: tornquist --- .github/workflows/_ci-relay.yml | 2 ++ 1 file changed, 2 insertions(+) diff --git a/.github/workflows/_ci-relay.yml b/.github/workflows/_ci-relay.yml index b616b8e7f35..cf87d7a6cad 100644 --- a/.github/workflows/_ci-relay.yml +++ b/.github/workflows/_ci-relay.yml @@ -198,6 +198,8 @@ jobs: with: name: desktop-e2e-relay path: target/ci + - name: Restore relay executable permission + run: chmod +x ./target/ci/buzz-relay - name: PostgreSQL-backed tests env: BUZZ_POSTGRES_ADMIN_URL: postgres://buzz:${{ env.BUZZ_TEST_POSTGRES_PASSWORD }}@localhost:5432/postgres From 63bc7b466c6bedfe34e9a5980e1de023e34d362f Mon Sep 17 00:00:00 2001 From: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Date: Wed, 16 Sep 2026 07:15:10 +0000 Subject: [PATCH 04/17] fix(relay): sample readiness once per probe Co-authored-by: Codex Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Signed-off-by: tornquist --- crates/buzz-relay/src/metrics.rs | 2 +- crates/buzz-relay/src/readiness.rs | 78 +++++------------------------- crates/buzz-relay/src/router.rs | 18 +++++-- crates/buzz-relay/src/state.rs | 5 +- deploy/charts/buzz/README.md | 5 +- 5 files changed, 34 insertions(+), 74 deletions(-) diff --git a/crates/buzz-relay/src/metrics.rs b/crates/buzz-relay/src/metrics.rs index bed10e68c3b..6d01ca3bf45 100644 --- a/crates/buzz-relay/src/metrics.rs +++ b/crates/buzz-relay/src/metrics.rs @@ -329,7 +329,7 @@ pub(crate) fn describe_readiness_metrics() { ); metrics::describe_gauge!( "buzz_readiness_state", - "Local readiness of this process, where 1 is ready and 0 is shutting down" + "Latest private readiness-probe observation, where 1 is ready and 0 is shutting down" ); } diff --git a/crates/buzz-relay/src/readiness.rs b/crates/buzz-relay/src/readiness.rs index c64f29407b9..0dfb5319e15 100644 --- a/crates/buzz-relay/src/readiness.rs +++ b/crates/buzz-relay/src/readiness.rs @@ -56,28 +56,16 @@ impl ReadinessReason { /// Records one readiness probe served by the private health listener. /// -/// `still_ready` re-reads process lifecycle *after* the gauge is written. That -/// ordering is the whole fence: `begin_shutdown` is one-way, so a probe that -/// sampled `Ready` immediately before it must not leave a stale ready gauge -/// behind for the rest of the drain. Re-reading before the write would reopen -/// the same window. Nothing else about a probe is shared, so this replaces the -/// generation-fenced coordinator the dependency probe used to require. -pub(crate) fn record_readiness_probe(reason: ReadinessReason, still_ready: impl FnOnce() -> bool) { +/// The counter and gauge describe the same immutable lifecycle observation. +/// The gauge is therefore the latest private readiness-probe observation, not +/// a transition-owned lifecycle mirror. +pub(crate) fn record_readiness_probe(reason: ReadinessReason) { metrics::counter!( "buzz_readiness_checks_total", "reason" => reason.label(), ) .increment(1); - record_overall_state(reason.is_ready()); - if !still_ready() { - record_overall_state(false); - } -} - -/// Publishes the overall readiness gauge. Called by the probe and by terminal -/// shutdown, so a draining pod reports not-ready before its next scrape. -pub(crate) fn record_overall_state(ready: bool) { - metrics::gauge!("buzz_readiness_state", "check" => "overall").set(if ready { + metrics::gauge!("buzz_readiness_state", "check" => "overall").set(if reason.is_ready() { 1.0 } else { 0.0 @@ -606,16 +594,17 @@ mod tests { ); } - /// The readiness gauge and counter follow lifecycle only. A dependency - /// evaluation — however bad — must never move them, which is what let a - /// shared outage deroute every replica at once. + /// The readiness gauge and counter use the same immutable reason sampled by + /// the private probe. A dependency evaluation — however bad — must never + /// move them, which is what let a shared outage deroute every replica at + /// once. #[test] fn readiness_telemetry_tracks_lifecycle_and_dependency_failure_never_moves_it() { let recorder = DebuggingRecorder::new(); let snapshotter = recorder.snapshotter(); metrics::with_local_recorder(&recorder, || { - record_readiness_probe(ReadinessReason::Ready, || true); + record_readiness_probe(ReadinessReason::Ready); record_dependency_report(&redis_failure_report()); }); let after_failure = snapshotter.snapshot().into_vec(); @@ -653,7 +642,7 @@ mod tests { } metrics::with_local_recorder(&recorder, || { - record_readiness_probe(ReadinessReason::ShuttingDown, || false); + record_readiness_probe(ReadinessReason::ShuttingDown); }); let after_shutdown = snapshotter.snapshot().into_vec(); @@ -668,47 +657,6 @@ mod tests { )); } - /// The publication fence. A probe that sampled `Ready` a moment before - /// `begin_shutdown` landed must not leave the gauge advertising ready for - /// the rest of the drain. Deleting the post-write re-read fails the first - /// case below. - #[test] - fn a_probe_that_raced_shutdown_cannot_leave_a_ready_gauge() { - for (sampled, still_ready, expected, case) in [ - ( - ReadinessReason::Ready, - false, - 0.0, - "shutdown landed mid-probe", - ), - (ReadinessReason::Ready, true, 1.0, "no shutdown"), - ( - ReadinessReason::ShuttingDown, - false, - 0.0, - "already draining", - ), - ( - ReadinessReason::ShuttingDown, - true, - 0.0, - "sampled shutdown never publishes ready", - ), - ] { - let recorder = DebuggingRecorder::new(); - let snapshotter = recorder.snapshotter(); - metrics::with_local_recorder(&recorder, || { - record_readiness_probe(sampled, || still_ready); - }); - - assert_eq!( - gauge_value(&snapshotter.snapshot().into_vec(), "overall"), - expected, - "{case}" - ); - } - } - /// A shutdown probe records no dependency attempt or latency sample: it did /// not evaluate anything, and fabricating a sample would misreport the /// dependency's real health during a rollout. @@ -718,8 +666,8 @@ mod tests { let snapshotter = recorder.snapshotter(); metrics::with_local_recorder(&recorder, || { - record_readiness_probe(ReadinessReason::Ready, || true); - record_readiness_probe(ReadinessReason::ShuttingDown, || false); + record_readiness_probe(ReadinessReason::Ready); + record_readiness_probe(ReadinessReason::ShuttingDown); }); let snapshot = snapshotter.snapshot().into_vec(); diff --git a/crates/buzz-relay/src/router.rs b/crates/buzz-relay/src/router.rs index 15b520c0673..76cba0d1ffb 100644 --- a/crates/buzz-relay/src/router.rs +++ b/crates/buzz-relay/src/router.rs @@ -652,10 +652,11 @@ async fn public_readiness_handler(State(state): State>) -> impl In } /// Kubernetes health-listener endpoint — the only source of rollout readiness -/// telemetry. +/// telemetry. Its single lifecycle sample determines every observable result +/// of this request: counter, gauge, HTTP status, and body. async fn kubernetes_readiness_handler(State(state): State>) -> impl IntoResponse { let reason = readiness_reason(&state); - readiness::record_readiness_probe(reason, || readiness_reason(&state).is_ready()); + readiness::record_readiness_probe(reason); readiness_response(reason) } @@ -1080,8 +1081,9 @@ mod tests { /// The frozen telemetry contract for the health listener. /// /// Readiness is lifecycle-only: its counter carries exactly two reasons and - /// its gauge follows shutdown, never a dependency. Dependency families are - /// still exported, but only by the diagnostic `/_status` endpoint, and + /// its gauge is the latest private readiness-probe observation, never a + /// dependency or a transition-owned lifecycle mirror. Dependency families + /// are still exported, but only by the diagnostic `/_status` endpoint, and /// public-listener traffic moves nothing. #[test] fn production_health_routes_export_the_frozen_telemetry_contract() { @@ -1240,6 +1242,14 @@ mod tests { .render() .lines() .all(|line| !line.contains("reason=\"shutting_down\""))); + assert_eq!( + metric_value( + &handle.render(), + "buzz_readiness_state{check=\"overall\"}" + ), + 1.0, + "shutdown and public traffic must not update the private probe gauge" + ); assert_eq!( readiness_request(health).await, diff --git a/crates/buzz-relay/src/state.rs b/crates/buzz-relay/src/state.rs index 592dc2d9eb7..7aad8c05e8d 100644 --- a/crates/buzz-relay/src/state.rs +++ b/crates/buzz-relay/src/state.rs @@ -1097,11 +1097,10 @@ impl AppState { } /// Withdraws this pod from routing. The lifecycle flag is authoritative for - /// `/_readiness`; the gauge is published immediately so a draining pod does - /// not report ready until its next probe. + /// `/_readiness`; the private probe publishes its sampled observation to + /// the readiness gauge on its next request. pub fn begin_shutdown(&self) { self.shutting_down.store(true, Ordering::Release); - crate::readiness::record_overall_state(false); } #[cfg(test)] diff --git a/deploy/charts/buzz/README.md b/deploy/charts/buzz/README.md index 5920432ffcf..2d878633716 100644 --- a/deploy/charts/buzz/README.md +++ b/deploy/charts/buzz/README.md @@ -151,7 +151,7 @@ listener returns the same lifecycle answer but does not change these metrics. | Metric | Type | Labels | Source | |--------|------|--------|--------| | `buzz_readiness_checks_total` | counter | `reason` ∈ {`ready`, `shutting_down`} | `/_readiness` | -| `buzz_readiness_state` | gauge | `check="overall"`; 1 ready, 0 shutting down | `/_readiness`, shutdown | +| `buzz_readiness_state` | gauge | `check="overall"`; latest private probe observation, 1 ready or 0 shutting down | `/_readiness` | | `buzz_readiness_dependency_checks_total` | counter | `dependency`, typed bounded `outcome` | `/_status` | | `buzz_readiness_check_duration_seconds` | histogram | `check` only | `/_status` | @@ -164,6 +164,9 @@ The schema has a ceiling of 86 raw Prometheus series per pod: 2 probe reasons, pod, ReplicaSet, version, rollout, error text, SQL, URL, tenant, user, community, pubkey, header, query, or other request-controlled labels. A readiness probe records no dependency attempt or latency sample at all. +The gauge is not a monotonic lifecycle mirror: shutdown changes the +authoritative lifecycle flag, and the next private readiness probe observes and +publishes that state. ### Community admission telemetry From 706301d95af7a69aa5734adae7e4e372c103f8ff Mon Sep 17 00:00:00 2001 From: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Date: Wed, 16 Sep 2026 12:07:03 +0000 Subject: [PATCH 05/17] fix(relay): fail closed when the community lifecycle lookup errors Socket admission treated a failed `is_community_active` lookup as grounds to admit, deferring eviction to the periodic revalidator. That begins serving AUTH and REQ frames for a tenant whose lifecycle is unknown, which `docs/multi-tenant-relay.md` I5 (`Inv_AdmissionFence`) does not permit: read and membership capability belong only to an actor currently admitted to that community. The adjacent host-binding seam already refuses on exactly this evidence. Both non-affirmative outcomes now cancel before any frame is read. The `buzz_community_admission_checks_total{outcome}` counter still separates `inactive` from `check_error`, so an operator can tell archival from database pressure without the admission decision depending on that distinction. Co-Authored-By: Claude Opus 5 Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Signed-off-by: tornquist --- crates/buzz-relay/src/state.rs | 56 +++++++++++++++++++++------------- deploy/charts/buzz/README.md | 11 ++++--- 2 files changed, 41 insertions(+), 26 deletions(-) diff --git a/crates/buzz-relay/src/state.rs b/crates/buzz-relay/src/state.rs index 7aad8c05e8d..ca757982e66 100644 --- a/crates/buzz-relay/src/state.rs +++ b/crates/buzz-relay/src/state.rs @@ -268,10 +268,13 @@ fn record_admission_check(outcome: AdmissionOutcome) { /// The ordering is the archival admission invariant: archive-before-query is /// observed by the query, while archive-after-registration sees the token. /// -/// Only a confirmed `Ok(false)` cancels. A lookup `Err` admits the socket and -/// defers to [`AppState::revalidate_live_communities`], because a database blip -/// is not evidence of archival and dropping sockets on one amplifies the very -/// pressure that caused it. +/// Admission is fail-closed: only an affirmative `Ok(true)` may serve. Both +/// `Ok(false)` and a lookup `Err` cancel, because neither proves this tenant is +/// currently admitted, and `docs/multi-tenant-relay.md` I5 +/// (`Inv_AdmissionFence`) grants capability only to an actor *currently* +/// admitted to that community. The two are still told apart in telemetry +/// (`buzz_community_admission_checks_total{outcome}`) so an operator can +/// separate archival from database pressure. pub(crate) async fn run_registered_community_connection( registry: &CommunityConnectionRegistry, connection_id: Uuid, @@ -295,19 +298,20 @@ pub(crate) async fn run_registered_community_connection { - // A lookup failure is not an answer, and dropping the socket on one - // turns shared database pressure into a reconnect storm that feeds - // straight back into the exhausted pool. Admitting costs nothing - // durable: writes still fail closed on their own per-event fence - // (`handlers::ingest::map_serving_fence_state`), and - // `AppState::revalidate_live_communities` closes the socket on the - // next tick if the community really is inactive. + // A lookup failure is not an answer, so it cannot authorize one. + // Admitting here would begin serving AUTH and REQ for a tenant + // whose lifecycle is unknown, and the adjacent host-binding seam + // already refuses on exactly this evidence (see + // `router::nip11_or_ws_handler`). The client sees an ordinary dial + // failure and retries. record_admission_check(AdmissionOutcome::CheckError); tracing::warn!( %community_id, %error, - "community active check failed; admitting the socket pending lifecycle revalidation" + "community active check failed; refusing the socket" ); + cancel.cancel(); + return; } } if cancel.is_cancelled() { @@ -2230,13 +2234,15 @@ pub(crate) mod tests { }) } - /// The reconnect-amplification regression. A durable *answer* of "inactive" - /// cancels the socket, but a lookup *failure* is not an answer: the socket is - /// admitted and the periodic revalidation backstop owns eviction. Collapsing - /// both into "not active" turned shared database pressure into a reconnect - /// storm that fed straight back into the exhausted pool. + /// Admission is fail-closed on both non-affirmative outcomes. A confirmed + /// `Ok(false)` and a lookup `Err` are different diagnoses — the counter + /// keeps them apart — but neither is proof of current admission, and + /// `docs/multi-tenant-relay.md` I5 (`Inv_AdmissionFence`) grants read or + /// membership capability only to an actor *currently* admitted to that + /// community. Serving AUTH/REQ on an unproven tenant lifecycle is the + /// failure this guards. #[test] - fn confirmed_inactive_cancels_while_an_active_check_error_admits_the_socket() { + fn neither_a_confirmed_inactive_community_nor_a_failed_lookup_admits_the_socket() { let runtime = tokio::runtime::Builder::new_current_thread() .enable_all() .build() @@ -2244,7 +2250,7 @@ pub(crate) mod tests { let recorder = metrics_util::debugging::DebuggingRecorder::new(); let snapshotter = recorder.snapshotter(); - let (inactive_cancel, inactive_started, error_started, active_started) = + let (inactive_cancel, inactive_started, error_cancel, error_started, active_started) = metrics::with_local_recorder(&recorder, || { runtime.block_on(async { let registry = CommunityConnectionRegistry::new(); @@ -2263,13 +2269,14 @@ pub(crate) mod tests { ) .await; + let error_cancel = CancellationToken::new(); let error_started = Arc::new(AtomicBool::new(false)); let started = Arc::clone(&error_started); run_registered_community_connection( ®istry, Uuid::new_v4(), community, - CommunityConnectionControl::new(CancellationToken::new()), + CommunityConnectionControl::new(error_cancel.clone()), || async { Err(buzz_db::DbError::Sqlx(sqlx::Error::PoolTimedOut)) }, move |_| async move { started.store(true, Ordering::SeqCst) }, ) @@ -2290,6 +2297,7 @@ pub(crate) mod tests { ( inactive_cancel, inactive_started, + error_cancel, error_started, active_started, ) @@ -2305,8 +2313,12 @@ pub(crate) mod tests { "a confirmed-inactive community must never start the socket body" ); assert!( - error_started.load(Ordering::SeqCst), - "an active-check error must admit the socket and leave eviction to revalidation" + error_cancel.is_cancelled(), + "a failed active check must cancel its socket, not admit it" + ); + assert!( + !error_started.load(Ordering::SeqCst), + "a failed active check must never start serving AUTH/REQ on an unproven tenant" ); assert!(active_started.load(Ordering::SeqCst)); diff --git a/deploy/charts/buzz/README.md b/deploy/charts/buzz/README.md index 2d878633716..095eb62d5a6 100644 --- a/deploy/charts/buzz/README.md +++ b/deploy/charts/buzz/README.md @@ -174,10 +174,13 @@ publishes that state. |--------|------|--------| | `buzz_community_admission_checks_total` | counter | `outcome` ∈ {`active`, `inactive`, `check_error`} | -Counts the durable community-active check run when a socket is admitted. -`inactive` is a confirmed answer and cancels the socket; `check_error` is a -lookup failure and admits it, leaving eviction to the periodic lifecycle -revalidator. `outcome` is the only dimension — community and error text are +Counts the durable community-active check run before a socket is admitted. +Admission is fail-closed: only `active` serves. `inactive` (a confirmed +archival answer) and `check_error` (the lookup itself failed, so the tenant +lifecycle is unknown) both refuse the socket before any AUTH or REQ frame is +read; the client sees an ordinary dial failure and retries. The two outcomes +stay distinct so a rise in `check_error` reads as database pressure rather than +archival. `outcome` is the only dimension — community and error text are request-controlled and must never become labels. ### Operation-aware database pool acquisition contract From 6195b725f5a72b0c67b61f308b1b5d0aaaddf9d2 Mon Sep 17 00:00:00 2001 From: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Date: Wed, 16 Sep 2026 13:52:07 +0000 Subject: [PATCH 06/17] refactor(relay): sample dependencies on a bounded per-pod loop MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `/_status` evaluated Postgres, Redis, and the deletion catalog on every request. That made the load a pressured dependency sees a function of how often someone looked at the endpoint, with nothing bounding how many evaluations could be in flight, and it left the dependency metrics flat whenever nobody was looking — during exactly the outage they exist to explain. `DependencyDiagnostics` now owns one fixed-cadence loop (`run_dependency_sampler`, 30s) that is the sole caller of the evaluator. It awaits each evaluation before taking the next tick, so a pod never holds more than one open; a dependency slower than the cadence lowers the sampling rate instead of stacking probes on the slowness that caused it. Each cycle republishes the existing dependency counters and histograms and caches the report with its observation time. `/_status` now only reads that cache and performs no dependency I/O, so it can be polled freely. Its `dependencies` object always carries a `sample` field — `not_yet_sampled`, `fresh`, or `stale` — plus the report's age, so a cached verdict can never be mistaken for a current one. Freshness is also observable from a scrape alone via a new `buzz_readiness_dependency_sample_age_seconds` gauge, following the existing `buzz_storage_sweep_age_seconds` convention: absent until the first report exists, so absence means "not yet sampled" rather than "fresh". The per-pod series ceiling moves from 86 to 87. `/_readiness` is untouched: still process-local lifecycle, still one sample per probe, same response and telemetry contract. Co-Authored-By: Claude Opus 5 Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Signed-off-by: tornquist --- crates/buzz-relay/src/lib.rs | 3 +- crates/buzz-relay/src/main.rs | 14 ++ crates/buzz-relay/src/metrics.rs | 16 +- crates/buzz-relay/src/readiness.rs | 267 +++++++++++++++++++++++-- crates/buzz-relay/src/router.rs | 311 ++++++++++++++++++++++++++--- crates/buzz-relay/src/state.rs | 8 +- deploy/charts/buzz/README.md | 57 ++++-- docs/deployment-identity.md | 12 +- 8 files changed, 619 insertions(+), 69 deletions(-) diff --git a/crates/buzz-relay/src/lib.rs b/crates/buzz-relay/src/lib.rs index 6991ebd3681..70f3ef4892a 100644 --- a/crates/buzz-relay/src/lib.rs +++ b/crates/buzz-relay/src/lib.rs @@ -45,7 +45,8 @@ pub mod operator_listener; pub mod protocol; /// Durable NIP-PL matcher and delivery worker. pub mod push_runtime; -mod readiness; +/// Readiness-probe telemetry and the per-pod dependency sampler behind `/_status`. +pub mod readiness; /// Axum router construction. pub mod router; /// Shared application state. diff --git a/crates/buzz-relay/src/main.rs b/crates/buzz-relay/src/main.rs index cf34af60159..0cc665dc2b8 100644 --- a/crates/buzz-relay/src/main.rs +++ b/crates/buzz-relay/src/main.rs @@ -1106,6 +1106,19 @@ async fn run_relay_main(boot: BootTracker) -> anyhow::Result<()> { )); } + // Per-pod dependency sampler: the single owner of Postgres/Redis/deletion- + // catalog evaluation. It publishes the dependency metrics and caches the + // report `/_status` serves, so neither operator polling nor a quiet endpoint + // changes how often a shared dependency is probed. + { + let sampler_state = Arc::clone(&state); + let cancel = sampler_state.dependency_sampler_cancel.clone(); + tokio::spawn(buzz_relay::readiness::run_dependency_sampler( + sampler_state, + cancel, + )); + } + // Cross-pod connection-control consumer: receive disconnect commands from // Redis pub/sub (published by the pod that recorded a ban) and close any // matching local sockets. A member's live connections may land on any pod, @@ -1279,6 +1292,7 @@ async fn run_relay_main(boot: BootTracker) -> anyhow::Result<()> { serve(router, health_router, Arc::clone(&state)).await?; state.community_revalidator_cancel.cancel(); + state.dependency_sampler_cancel.cancel(); // Signal the audit worker to stop accepting, flush buffered entries, and // exit. Uses a CancellationToken so it works regardless of how many diff --git a/crates/buzz-relay/src/metrics.rs b/crates/buzz-relay/src/metrics.rs index 6d01ca3bf45..40d7ac9bf87 100644 --- a/crates/buzz-relay/src/metrics.rs +++ b/crates/buzz-relay/src/metrics.rs @@ -310,9 +310,10 @@ pub fn install(port: u16, gauge_idle_timeout_secs: u64) { /// Register the frozen readiness and dependency-diagnostic metric descriptions. /// /// The two `buzz_readiness_*` probe families describe local process lifecycle. -/// The two dependency families keep their names for dashboard continuity but -/// are sampled by the diagnostic `/_status` endpoint, not by the Kubernetes -/// probe — a shared-dependency failure no longer deroutes the pod. +/// The dependency families keep their names for dashboard continuity but are +/// published by the per-pod dependency sampler, not by the Kubernetes probe or +/// by an `/_status` request — a shared-dependency failure no longer deroutes +/// the pod, and nobody has to read the endpoint for the metrics to move. pub(crate) fn describe_readiness_metrics() { metrics::describe_counter!( "buzz_readiness_checks_total", @@ -320,17 +321,22 @@ pub(crate) fn describe_readiness_metrics() { ); metrics::describe_counter!( "buzz_readiness_dependency_checks_total", - "Completed /_status dependency attempts by dependency and bounded outcome" + "Completed dependency-sampler attempts by dependency and bounded outcome" ); metrics::describe_histogram!( "buzz_readiness_check_duration_seconds", metrics::Unit::Seconds, - "Completed /_status dependency check duration without outcome label multiplication" + "Completed dependency-sampler check duration without outcome label multiplication" ); metrics::describe_gauge!( "buzz_readiness_state", "Latest private readiness-probe observation, where 1 is ready and 0 is shutting down" ); + metrics::describe_gauge!( + "buzz_readiness_dependency_sample_age_seconds", + metrics::Unit::Seconds, + "Age of the cached /_status dependency report, absent until the first sample completes" + ); } /// Register the bounded community-admission contract. diff --git a/crates/buzz-relay/src/readiness.rs b/crates/buzz-relay/src/readiness.rs index 0dfb5319e15..3b796519ebc 100644 --- a/crates/buzz-relay/src/readiness.rs +++ b/crates/buzz-relay/src/readiness.rs @@ -7,16 +7,40 @@ //! process's own lifecycle (see [`crate::router`]), and the same dependency //! evaluation is reported on the diagnostic `/_status` endpoint, which is never //! wired to a probe. +//! +//! Dependency evaluation is also decoupled from requests. One per-pod loop +//! ([`run_dependency_sampler`]) evaluates on a fixed cadence, publishes the +//! dependency metrics, and caches the report; `/_status` only reads that cache. +//! Evaluating per request made the load a pressured dependency sees depend on +//! how often someone looked at the endpoint, with nothing bounding how many +//! evaluations could be in flight at once. use std::future::Future; -use std::sync::Arc; +use std::sync::{Arc, Mutex, PoisonError}; use std::time::Duration; use buzz_db::{Db, DbError, DbReadinessOutcome}; use tokio::time::Instant; +use tokio_util::sync::CancellationToken; + +use crate::state::AppState; const DEPENDENCY_TIMEOUT: Duration = Duration::from_secs(2); +/// Fixed cadence of the per-pod dependency sampling loop. +/// +/// Slow enough that a pod adds negligible load to a shared dependency, fast +/// enough that an operator opening `/_status` during an incident reads +/// something current. Documented in `deploy/charts/buzz/README.md`. +pub const DEPENDENCY_SAMPLE_INTERVAL: Duration = Duration::from_secs(30); + +/// Age past which a cached report is reported stale rather than current. +/// +/// Two cadences: one full cycle can be missed by an evaluation that consumed +/// its whole [`DEPENDENCY_TIMEOUT`] budget, so anything older than that means +/// the sampler itself is not keeping up. +const DEPENDENCY_SAMPLE_STALE_AFTER: Duration = DEPENDENCY_SAMPLE_INTERVAL.saturating_mul(2); + /// Closed label set exported by `buzz_readiness_checks_total{reason}`. /// /// Readiness answers a local lifecycle question, so this set cannot grow with @@ -31,8 +55,9 @@ pub(crate) const READINESS_REASON_LABELS: [&str; 2] = ["ready", "shutting_down"] /// - 11 valid dependency/outcome pairs (Postgres 5, Redis 3, catalog 3) /// - 4 histograms x (15 configured buckets + `+Inf` + count + sum) = 72 /// - 1 overall readiness gauge +/// - 1 dependency-sample age gauge #[cfg(test)] -pub(crate) const READINESS_RAW_SERIES_PER_POD: usize = 2 + 11 + (4 * 18) + 1; +pub(crate) const READINESS_RAW_SERIES_PER_POD: usize = 2 + 11 + (4 * 18) + 1 + 1; /// Terminal outcome of one readiness probe. #[derive(Debug, Clone, Copy, PartialEq, Eq)] @@ -384,45 +409,116 @@ impl DependencyEvaluator for ProductionDependencyEvaluator { } } -/// Evaluates shared-dependency health for the diagnostic `/_status` endpoint. +/// One completed evaluation and when it was observed. +#[derive(Debug, Clone, Copy)] +struct DependencySample { + report: DependencyReport, + observed_at: Instant, +} + +/// What the cache can tell `/_status`. +/// +/// "No report yet" is a distinct state, not a fabricated healthy one, and a +/// report is always accompanied by its age: a cached verdict presented without +/// one would read as authoritative however long ago it was taken. +#[derive(Debug, Clone, Copy)] +pub(crate) enum DependencySnapshot { + /// The sampler has not completed its first evaluation yet. + NotYetSampled, + Sampled { + report: DependencyReport, + age: Duration, + stale: bool, + }, +} + +/// The per-pod owner of shared-dependency evaluation. /// -/// This deliberately owns no publication fence. It publishes no gauge, so two -/// concurrent `/_status` requests cannot reorder any shared state — the fence -/// the readiness coordinator used to need went away with the dependency probe. +/// [`run_dependency_sampler`] is the only caller of [`Self::sample`], so at +/// most one evaluation exists at a time and no request path can start another. +/// `/_status` reads [`Self::snapshot`], which touches no dependency. pub(crate) struct DependencyDiagnostics { evaluator: Arc, + latest: Mutex>, } impl Default for DependencyDiagnostics { fn default() -> Self { - Self { - evaluator: Arc::new(ProductionDependencyEvaluator), - } + Self::with_evaluator(Arc::new(ProductionDependencyEvaluator)) } } impl DependencyDiagnostics { - #[cfg(test)] pub(crate) fn with_evaluator(evaluator: Arc) -> Self { - Self { evaluator } + Self { + evaluator, + latest: Mutex::new(None), + } } - /// Runs one bounded dependency evaluation and records its telemetry. - pub(crate) async fn evaluate( - &self, - db: &Db, - redis_pool: &deadpool_redis::Pool, - ) -> DependencyReport { + /// Runs one bounded evaluation, publishes its telemetry, and replaces the + /// cached report. + /// + /// The age gauge is published first, while the cache still holds the report + /// this cycle is about to replace — that is the age a scrape would have + /// read, and it grows whenever a cycle runs late. + pub(crate) async fn sample(&self, db: &Db, redis_pool: &deadpool_redis::Pool) { + record_dependency_sample_age(self.snapshot()); let report = self.evaluator.evaluate(db, redis_pool).await; record_dependency_report(&report); - report + let sample = DependencySample { + report, + observed_at: Instant::now(), + }; + *self.latest.lock().unwrap_or_else(PoisonError::into_inner) = Some(sample); + } + + /// The latest completed evaluation with its age. Starts no dependency work. + pub(crate) fn snapshot(&self) -> DependencySnapshot { + let latest = *self.latest.lock().unwrap_or_else(PoisonError::into_inner); + match latest { + None => DependencySnapshot::NotYetSampled, + Some(sample) => { + let age = sample.observed_at.elapsed(); + DependencySnapshot::Sampled { + report: sample.report, + age, + stale: age > DEPENDENCY_SAMPLE_STALE_AFTER, + } + } + } + } +} + +/// Runs the per-pod dependency sampling loop until `cancel` fires. +/// +/// One loop, one fixed cadence, each evaluation awaited before the next tick is +/// taken, so this pod never has two evaluations in flight. `Skip` matches the +/// community revalidator: an evaluation that overruns its slot delays the next +/// cycle instead of queueing a catch-up burst into the dependency that was +/// already slow. The first tick fires immediately, so the not-yet-sampled +/// window is one evaluation long. +pub async fn run_dependency_sampler(state: Arc, cancel: CancellationToken) { + let mut interval = tokio::time::interval(DEPENDENCY_SAMPLE_INTERVAL); + interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Skip); + loop { + tokio::select! { + biased; + _ = cancel.cancelled() => break, + _ = interval.tick() => { + state + .dependency_diagnostics + .sample(&state.db, &state.redis_pool) + .await; + } + } } } /// Records one dependency evaluation. Counters and durations only — dependency -/// health has no publishable "current state" now that no probe consumes it, and -/// a gauge driven by ad-hoc `/_status` requests would read as authoritative -/// while going stale between operator visits. +/// health has no publishable "current state" now that no probe consumes it; a +/// per-dependency gauge would read as an authoritative verdict on infrastructure +/// this pod only samples every [`DEPENDENCY_SAMPLE_INTERVAL`]. fn record_dependency_report(report: &DependencyReport) { metrics::histogram!( "buzz_readiness_check_duration_seconds", @@ -443,6 +539,15 @@ fn record_dependency_report(report: &DependencyReport) { ); } +/// Publishes the age of the cached report, following the +/// `buzz_storage_sweep_age_seconds` convention: absent until a report exists, +/// so absence means "not yet sampled" rather than "fresh". +fn record_dependency_sample_age(snapshot: DependencySnapshot) { + if let DependencySnapshot::Sampled { age, .. } = snapshot { + metrics::gauge!("buzz_readiness_dependency_sample_age_seconds").set(age.as_secs_f64()); + } +} + fn record_dependency_attempt(dependency: &'static str, outcome: &'static str, duration: Duration) { metrics::counter!( "buzz_readiness_dependency_checks_total", @@ -579,7 +684,7 @@ mod tests { .map(DeletionCatalogOutcome::label), ["success", "operation_timeout", "operation_error"] ); - assert_eq!(READINESS_RAW_SERIES_PER_POD, 86); + assert_eq!(READINESS_RAW_SERIES_PER_POD, 87); } #[test] @@ -677,6 +782,124 @@ mod tests { })); } + /// A `Db` and a Redis pool on a closed port. The scripted evaluators below + /// never touch either, so no connection is ever attempted; they exist only + /// to satisfy the production `sample` signature. + fn unreachable_dependencies() -> (Db, deadpool_redis::Pool) { + let pool = sqlx::PgPool::connect_lazy("postgres://127.0.0.1:1/buzz").expect("lazy pg pool"); + let redis_pool = deadpool_redis::Config::from_url("redis://127.0.0.1:1") + .create_pool(Some(deadpool_redis::Runtime::Tokio1)) + .expect("redis pool"); + (Db::from_pool(pool), redis_pool) + } + + struct FixedEvaluator(DependencyReport); + + #[async_trait::async_trait] + impl DependencyEvaluator for FixedEvaluator { + async fn evaluate(&self, _db: &Db, _redis_pool: &deadpool_redis::Pool) -> DependencyReport { + self.0 + } + } + + fn ready_diagnostics() -> DependencyDiagnostics { + DependencyDiagnostics::with_evaluator(Arc::new(FixedEvaluator( + DependencyReport::from_results( + TimedOutcome::new(PostgresOutcome::Success, Duration::from_millis(3)), + TimedOutcome::new(RedisOutcome::Success, Duration::from_millis(2)), + TimedOutcome::new(DeletionCatalogOutcome::Success, Duration::from_millis(1)), + Duration::from_millis(3), + ), + ))) + } + + fn sampled(snapshot: DependencySnapshot) -> (Duration, bool) { + let DependencySnapshot::Sampled { age, stale, .. } = snapshot else { + panic!("a completed sample must be reported as sampled"); + }; + (age, stale) + } + + /// An operator reading `/_status` must be able to tell "nothing has been + /// sampled yet" from "this is current" from "this outlived the sampler". + /// A cached report presented without its age would read as authoritative + /// however old it is. + #[tokio::test(start_paused = true)] + async fn freshness_separates_not_yet_sampled_from_a_fresh_and_a_stale_report() { + let (db, redis_pool) = unreachable_dependencies(); + let diagnostics = ready_diagnostics(); + + assert!( + matches!(diagnostics.snapshot(), DependencySnapshot::NotYetSampled), + "no evaluation has completed, so there is nothing to report" + ); + + diagnostics.sample(&db, &redis_pool).await; + assert_eq!(sampled(diagnostics.snapshot()), (Duration::ZERO, false)); + + tokio::time::advance(DEPENDENCY_SAMPLE_INTERVAL).await; + assert_eq!( + sampled(diagnostics.snapshot()), + (DEPENDENCY_SAMPLE_INTERVAL, false), + "one cadence of age is the steady state, not staleness" + ); + + tokio::time::advance(DEPENDENCY_SAMPLE_INTERVAL + Duration::from_secs(1)).await; + let (age, stale) = sampled(diagnostics.snapshot()); + assert_eq!(age, DEPENDENCY_SAMPLE_INTERVAL * 2 + Duration::from_secs(1)); + assert!(stale, "a report that outlived two cadences missed a cycle"); + } + + fn sample_age_gauge(snapshot: &Snapshot) -> Option { + exact_metric( + snapshot, + "buzz_readiness_dependency_sample_age_seconds", + &[], + ) + .map(|value| { + let DebugValue::Gauge(value) = value else { + panic!("sample age must be a gauge"); + }; + value.into_inner() + }) + } + + /// The scrape-side half of the same question. Following + /// `buzz_storage_sweep_age_seconds`, the gauge is absent until a report + /// exists and then carries the age of the cached report, so a sampler that + /// stops advancing it is visible without reading `/_status` at all. + #[test] + fn the_sample_age_gauge_is_absent_until_a_report_exists_then_carries_its_age() { + let runtime = tokio::runtime::Builder::new_current_thread() + .enable_all() + .start_paused(true) + .build() + .expect("paused current-thread runtime"); + let recorder = DebuggingRecorder::new(); + let snapshotter = recorder.snapshotter(); + + metrics::with_local_recorder(&recorder, || { + runtime.block_on(async { + let (db, redis_pool) = unreachable_dependencies(); + let diagnostics = ready_diagnostics(); + + diagnostics.sample(&db, &redis_pool).await; + assert_eq!( + sample_age_gauge(&snapshotter.snapshot().into_vec()), + None, + "the first cycle has no prior report whose age it could publish" + ); + + tokio::time::advance(DEPENDENCY_SAMPLE_INTERVAL).await; + diagnostics.sample(&db, &redis_pool).await; + assert_eq!( + sample_age_gauge(&snapshotter.snapshot().into_vec()), + Some(DEPENDENCY_SAMPLE_INTERVAL.as_secs_f64()) + ); + }); + }); + } + #[test] fn readiness_reason_labels_are_the_closed_lifecycle_set() { assert_eq!( diff --git a/crates/buzz-relay/src/router.rs b/crates/buzz-relay/src/router.rs index 76cba0d1ffb..6d5a32580c3 100644 --- a/crates/buzz-relay/src/router.rs +++ b/crates/buzz-relay/src/router.rs @@ -25,7 +25,7 @@ use crate::connection::handle_connection; use crate::metrics::track_metrics; use crate::nip11::{nip11_document, relay_info_handler}; use crate::nip_fi_http::http_denial; -use crate::readiness::{self, DependencyReport, ReadinessReason}; +use crate::readiness::{self, DependencySnapshot, ReadinessReason}; use crate::state::AppState; // ── NIP-FI fail-closed assertion guard ─────────────────────────────────────── @@ -703,29 +703,43 @@ fn status_payload(uptime_secs: u64) -> serde_json::Value { }) } -/// The dependency fields the readiness body used to carry, now diagnostic only. -fn dependency_diagnostics_payload(report: &DependencyReport) -> serde_json::Value { - json!({ - "postgres": report.postgres_ready(), - "redis": report.redis_ready(), - "deletion_catalog": report.deletion_catalog_ready(), - "reason": report.reason.label(), - }) +/// The dependency fields the readiness body used to carry, now a diagnostic +/// read of the sampler's cache. +/// +/// `sample` is always present so a reader can never mistake a cached verdict +/// for a current one: `not_yet_sampled` before the sampler's first evaluation +/// completes, then `fresh` or `stale` alongside the report's own age. +fn dependency_diagnostics_payload(snapshot: DependencySnapshot) -> serde_json::Value { + let interval_seconds = readiness::DEPENDENCY_SAMPLE_INTERVAL.as_secs(); + match snapshot { + DependencySnapshot::NotYetSampled => json!({ + "sample": "not_yet_sampled", + "sample_interval_seconds": interval_seconds, + }), + DependencySnapshot::Sampled { report, age, stale } => json!({ + "sample": if stale { "stale" } else { "fresh" }, + "sample_interval_seconds": interval_seconds, + "sample_age_seconds": age.as_secs(), + "postgres": report.postgres_ready(), + "redis": report.redis_ready(), + "deletion_catalog": report.deletion_catalog_ready(), + "reason": report.reason.label(), + }), + } } /// Status endpoint — service name, version, uptime, intrinsic build identity, -/// and shared-dependency diagnostics. +/// and the cached shared-dependency diagnostics. /// /// Health-listener only, and never wired to a Kubernetes probe: this is where /// an operator looks to tell "the pod is fine, Postgres is not" apart from "the -/// pod is broken". It is the only endpoint that touches the shared pools. +/// pod is broken". It reads only what +/// [`readiness::run_dependency_sampler`] has already cached, so however often +/// it is polled it adds no load to the shared pools. async fn status_handler(State(state): State>) -> impl IntoResponse { - let report = state - .dependency_diagnostics - .evaluate(&state.db, &state.redis_pool) - .await; let mut payload = status_payload(state.started_at.elapsed().as_secs()); - payload["dependencies"] = dependency_diagnostics_payload(&report); + payload["dependencies"] = + dependency_diagnostics_payload(state.dependency_diagnostics.snapshot()); Json(payload) } @@ -785,15 +799,18 @@ mod tests { use tracing_subscriber::prelude::*; use super::*; + use crate::readiness::DependencyReport; struct ScriptedDependencyEvaluator { evaluations: Mutex>, + evaluations_started: std::sync::atomic::AtomicUsize, } impl ScriptedDependencyEvaluator { fn new(evaluations: impl IntoIterator) -> Self { Self { evaluations: Mutex::new(evaluations.into_iter().collect()), + evaluations_started: std::sync::atomic::AtomicUsize::new(0), } } @@ -803,6 +820,11 @@ mod tests { .unwrap_or_else(PoisonError::into_inner) .push_back(evaluation); } + + /// How many times a caller actually reached the shared dependencies. + fn evaluations_started(&self) -> usize { + self.evaluations_started.load(Ordering::SeqCst) + } } #[async_trait::async_trait] @@ -812,6 +834,7 @@ mod tests { _db: &buzz_db::Db, _redis_pool: &deadpool_redis::Pool, ) -> DependencyReport { + self.evaluations_started.fetch_add(1, Ordering::SeqCst); self.evaluations .lock() .unwrap_or_else(PoisonError::into_inner) @@ -1035,7 +1058,9 @@ mod tests { } /// Dependency health did not disappear with the probe — it moved to the - /// diagnostic endpoint, which is never wired to a Kubernetes probe. + /// diagnostic endpoint, which is never wired to a Kubernetes probe. The + /// fields the readiness body used to carry are still there, now qualified + /// by how old the sample behind them is. #[tokio::test] async fn status_retains_dependency_diagnostics_off_the_probe_path() { let evaluator = Arc::new(ScriptedDependencyEvaluator::new([dependency_report( @@ -1044,6 +1069,10 @@ mod tests { readiness::DeletionCatalogOutcome::Success, )])); let state = readiness_state(evaluator).await; + state + .dependency_diagnostics + .sample(&state.db, &state.redis_pool) + .await; let (status, payload) = status_request(build_health_router(state)).await; @@ -1052,6 +1081,9 @@ mod tests { assert_eq!( payload["dependencies"], json!({ + "sample": "fresh", + "sample_interval_seconds": 30, + "sample_age_seconds": 0, "postgres": true, "redis": false, "deletion_catalog": true, @@ -1060,6 +1092,211 @@ mod tests { ); } + /// `/_status` is an operator diagnostic, not a dependency driver. Evaluating + /// per request let operator curiosity — and anything that polls the + /// endpoint — add Postgres, Redis, and deletion-catalog work to a shared + /// dependency that is already under pressure, with no bound on how many + /// evaluations could be in flight at once. The endpoint reads the cached + /// report the per-pod sampler owns and starts nothing. + #[tokio::test] + async fn status_reads_the_cached_report_and_never_starts_a_dependency_check() { + let evaluator = Arc::new(ScriptedDependencyEvaluator::new([ready_report()])); + let state = readiness_state(evaluator.clone()).await; + let health = build_health_router(state.clone()); + + for _ in 0..3 { + let (status, payload) = status_request(health.clone()).await; + assert_eq!(status, StatusCode::OK); + assert_eq!( + payload["dependencies"], + json!({ + "sample": "not_yet_sampled", + "sample_interval_seconds": 30, + }), + "before the first sample completes there is no report to serve" + ); + } + + assert_eq!( + evaluator.evaluations_started(), + 0, + "a status request must never reach the shared dependencies" + ); + + // Once the sampler has a report, and only then, the endpoint serves it. + state + .dependency_diagnostics + .sample(&state.db, &state.redis_pool) + .await; + let (status, payload) = status_request(health).await; + + assert_eq!(status, StatusCode::OK); + assert_eq!(payload["dependencies"]["sample"], json!("fresh")); + assert_eq!(payload["dependencies"]["reason"], json!("ready")); + assert_eq!( + evaluator.evaluations_started(), + 1, + "the sampler is the only caller that evaluates" + ); + } + + /// Always answers, recording how many evaluations started and the peak + /// number in flight, so a loop test can assert cadence and single-flight + /// without a scripted queue to exhaust. + struct ObservedDependencyEvaluator { + report: DependencyReport, + duration: Duration, + started: std::sync::atomic::AtomicUsize, + in_flight: std::sync::atomic::AtomicUsize, + peak_in_flight: std::sync::atomic::AtomicUsize, + } + + impl ObservedDependencyEvaluator { + fn new(report: DependencyReport, duration: Duration) -> Self { + Self { + report, + duration, + started: std::sync::atomic::AtomicUsize::new(0), + in_flight: std::sync::atomic::AtomicUsize::new(0), + peak_in_flight: std::sync::atomic::AtomicUsize::new(0), + } + } + + fn started(&self) -> usize { + self.started.load(Ordering::SeqCst) + } + + fn peak_in_flight(&self) -> usize { + self.peak_in_flight.load(Ordering::SeqCst) + } + } + + #[async_trait::async_trait] + impl readiness::DependencyEvaluator for ObservedDependencyEvaluator { + async fn evaluate( + &self, + _db: &buzz_db::Db, + _redis_pool: &deadpool_redis::Pool, + ) -> DependencyReport { + self.started.fetch_add(1, Ordering::SeqCst); + let in_flight = self.in_flight.fetch_add(1, Ordering::SeqCst) + 1; + self.peak_in_flight.fetch_max(in_flight, Ordering::SeqCst); + if !self.duration.is_zero() { + tokio::time::sleep(self.duration).await; + } + self.in_flight.fetch_sub(1, Ordering::SeqCst); + self.report + } + } + + /// Runs the production sampler on a paused clock for `window`, then cancels + /// it and returns the evaluator's observations. + async fn run_sampler_for( + evaluator: Arc, + window: Duration, + ) -> Arc { + let state = readiness_state(evaluator.clone()).await; + let cancel = state.dependency_sampler_cancel.clone(); + let sampler = tokio::spawn(readiness::run_dependency_sampler( + state.clone(), + cancel.clone(), + )); + tokio::time::sleep(window).await; + cancel.cancel(); + sampler.await.expect("sampler task"); + evaluator + } + + /// Dependency telemetry must keep describing the shared dependencies whether + /// or not anyone reads `/_status`. Request-driven evaluation meant a quiet + /// endpoint produced a flat dashboard during the exact outage it existed to + /// explain. + #[test] + fn the_dependency_sampler_emits_telemetry_without_any_request() { + let runtime = tokio::runtime::Builder::new_current_thread() + .enable_all() + .start_paused(true) + .build() + .expect("paused current-thread runtime"); + let (recorder, handle) = crate::metrics::readiness_test_recorder(); + + metrics::with_local_recorder(&recorder, || { + crate::metrics::describe_readiness_metrics(); + runtime.block_on(async { + // The first tick fires immediately, then one per cadence. + let evaluator = run_sampler_for( + Arc::new(ObservedDependencyEvaluator::new( + ready_report(), + Duration::ZERO, + )), + readiness::DEPENDENCY_SAMPLE_INTERVAL * 3 + Duration::from_secs(1), + ) + .await; + + assert_eq!(evaluator.started(), 4); + let rendered = handle.render(); + assert_eq!( + metric_value( + &rendered, + "buzz_readiness_dependency_checks_total{dependency=\"postgres\",outcome=\"success\"}" + ), + 4.0, + "every sampling cycle must publish its dependency outcomes" + ); + assert_eq!( + metric_value( + &rendered, + "buzz_readiness_check_duration_seconds_count{check=\"overall\"}" + ), + 4.0 + ); + assert!( + !rendered.contains("buzz_readiness_checks_total{"), + "sampling is not a readiness probe and must not move probe telemetry" + ); + }); + }); + } + + /// The bound that replaces the request-driven design's lack of one. The + /// sampler awaits each evaluation before taking the next tick, so a + /// dependency slower than the cadence lowers the sampling rate instead of + /// stacking probes on top of the slowness that caused it. + #[test] + fn the_dependency_sampler_never_runs_two_evaluations_at_once() { + let runtime = tokio::runtime::Builder::new_current_thread() + .enable_all() + .start_paused(true) + .build() + .expect("paused current-thread runtime"); + + runtime.block_on(async { + let slow = readiness::DEPENDENCY_SAMPLE_INTERVAL * 2 + Duration::from_secs(1); + let window = readiness::DEPENDENCY_SAMPLE_INTERVAL * 10; + let evaluator = run_sampler_for( + Arc::new(ObservedDependencyEvaluator::new(ready_report(), slow)), + window, + ) + .await; + + assert_eq!( + evaluator.peak_in_flight(), + 1, + "the sampler must own the only in-flight evaluation" + ); + // 61-second evaluations run back to back from t=0 in a 300-second + // window: five, not the ten ticks the cadence offered. An + // evaluation started per tick regardless of the last one would + // have started ten and held several open at once. + assert_eq!(evaluator.started(), 5); + assert!( + evaluator.started() + < (window.as_secs() / readiness::DEPENDENCY_SAMPLE_INTERVAL.as_secs()) as usize, + "a slow dependency must throttle sampling, not be sampled on every tick" + ); + }); + } + fn readiness_metric_lines(rendered: &str) -> Vec<&str> { rendered .lines() @@ -1083,17 +1320,17 @@ mod tests { /// Readiness is lifecycle-only: its counter carries exactly two reasons and /// its gauge is the latest private readiness-probe observation, never a /// dependency or a transition-owned lifecycle mirror. Dependency families - /// are still exported, but only by the diagnostic `/_status` endpoint, and - /// public-listener traffic moves nothing. + /// are still exported, but only by the per-pod sampler, and neither + /// public-listener traffic nor an `/_status` request moves anything. #[test] fn production_health_routes_export_the_frozen_telemetry_contract() { let runtime = tokio::runtime::Builder::new_current_thread() .enable_all() .build() .expect("current-thread runtime"); - // Seeded with the first `/_status` evaluation only; the coverage loop - // below pushes the rest, one per request, so the evaluator never - // serves a report the assertions did not choose. + // Seeded with the first sampling cycle only; the coverage loop below + // pushes the rest, one per cycle, so the evaluator never serves a + // report the assertions did not choose. let evaluator = Arc::new(ScriptedDependencyEvaluator::new([ready_report()])); let (recorder, handle) = crate::metrics::readiness_test_recorder(); @@ -1140,9 +1377,15 @@ mod tests { "the probe must not record a dependency latency sample" ); - // Dependency telemetry now belongs to the diagnostic endpoint. + // Dependency telemetry now belongs to the sampler; the + // endpoint only reads what the sampler cached. + state + .dependency_diagnostics + .sample(&state.db, &state.redis_pool) + .await; let (status, payload) = status_request(health.clone()).await; assert_eq!(status, StatusCode::OK); + assert_eq!(payload["dependencies"]["sample"], json!("fresh")); assert_eq!(payload["dependencies"]["reason"], json!("ready")); let after_status = handle.render(); assert!( @@ -1206,12 +1449,19 @@ mod tests { coverage.into_iter().enumerate() { evaluator.push(dependency_report(postgres, redis, deletion_catalog)); + state + .dependency_diagnostics + .sample(&state.db, &state.redis_pool) + .await; let (status, degraded) = status_request(health.clone()).await; assert_eq!(status, StatusCode::OK); if index == 0 { assert_eq!( degraded["dependencies"], json!({ + "sample": "fresh", + "sample_interval_seconds": 30, + "sample_age_seconds": 0, "postgres": false, "redis": false, "deletion_catalog": false, @@ -1279,6 +1529,19 @@ mod tests { 0.0 ); assert!(!final_scrape.contains("sensitive-sql-or-url")); + // Freshness is part of the frozen contract: one unlabelled + // gauge, published from the second cycle on, so a stalled + // sampler is visible from a scrape alone. + assert!(final_scrape + .contains("# TYPE buzz_readiness_dependency_sample_age_seconds gauge")); + assert_eq!( + final_scrape + .lines() + .filter(|line| line + .starts_with("buzz_readiness_dependency_sample_age_seconds")) + .count(), + 1 + ); let exported_reasons = final_scrape .lines() @@ -1288,7 +1551,7 @@ mod tests { assert_eq!( readiness_metric_lines(&final_scrape).len(), readiness::READINESS_RAW_SERIES_PER_POD, - "readiness series contract must stay at or below its 86-series cap" + "readiness series contract must stay at or below its 87-series cap" ); }); }); diff --git a/crates/buzz-relay/src/state.rs b/crates/buzz-relay/src/state.rs index ca757982e66..a297b6a9d4e 100644 --- a/crates/buzz-relay/src/state.rs +++ b/crates/buzz-relay/src/state.rs @@ -828,9 +828,12 @@ pub struct AppState { pub audio_rooms: Arc, /// Set to `true` on SIGTERM — readiness probe returns 503. pub shutting_down: Arc, - /// Shared-dependency evaluation behind the diagnostic `/_status` endpoint. - /// Never consulted by a Kubernetes probe. + /// Cached shared-dependency evaluation behind the diagnostic `/_status` + /// endpoint, owned by [`crate::readiness::run_dependency_sampler`]. Never + /// consulted by a Kubernetes probe, and never evaluated by a request. pub(crate) dependency_diagnostics: Arc, + /// Stops only the periodic dependency sampler during graceful shutdown. + pub dependency_sampler_cancel: CancellationToken, /// Process start time — used by `/_status` endpoint. pub started_at: Instant, /// Shared, community-scoped NIP-98 replay prevention. @@ -1057,6 +1060,7 @@ impl AppState { audio_rooms: Arc::new(AudioRoomManager::new()), shutting_down: Arc::new(AtomicBool::new(false)), dependency_diagnostics: Arc::new(crate::readiness::DependencyDiagnostics::default()), + dependency_sampler_cancel: CancellationToken::new(), started_at: Instant::now(), nip98_replay, gif_http_client, diff --git a/deploy/charts/buzz/README.md b/deploy/charts/buzz/README.md index 095eb62d5a6..3e5aea4fbd3 100644 --- a/deploy/charts/buzz/README.md +++ b/deploy/charts/buzz/README.md @@ -139,8 +139,28 @@ migrations, Redis, and pub/sub are up, so a process that can answer has booted. Shared-dependency health moved to **`/_status`** on the same private health listener, under a `dependencies` object carrying the `postgres`, `redis`, `deletion_catalog`, and aggregate `reason` fields the readiness body used to -return. Do not wire `/_status` to a Kubernetes probe; it is the only endpoint -that touches the shared pools. +return. Do not wire `/_status` to a Kubernetes probe. + +**`/_status` is a cached read.** It performs no Postgres, Redis, or +deletion-catalog I/O of its own. One background loop per pod evaluates the +three dependencies **every 30 seconds**, awaiting each evaluation before taking +the next tick, so a pod never has more than one evaluation in flight no matter +how often — or how rarely — the endpoint is read. The loop publishes the +dependency metrics below and caches the report `/_status` serves. Its first +cycle runs at startup, and each evaluation is bounded by a two-second budget. + +Every `dependencies` object therefore states how old its report is: + +| Field | Meaning | +|-------|---------| +| `sample: "not_yet_sampled"` | the first cycle has not completed; no `postgres`/`redis`/`deletion_catalog`/`reason` fields are present, because there is no observation to report | +| `sample: "fresh"` | the report is at most two cadences (60s) old | +| `sample: "stale"` | the report outlived two cadences, so the sampler missed at least one cycle — read the verdict as history, not as current state | +| `sample_age_seconds` | age of the report at request time (absent when `not_yet_sampled`) | +| `sample_interval_seconds` | the sampling cadence, `30` | + +Polling `/_status` more often than the cadence returns the same cached report; +it does not make the data fresher and adds no dependency load. ### Readiness telemetry contract @@ -152,19 +172,30 @@ listener returns the same lifecycle answer but does not change these metrics. |--------|------|--------|--------| | `buzz_readiness_checks_total` | counter | `reason` ∈ {`ready`, `shutting_down`} | `/_readiness` | | `buzz_readiness_state` | gauge | `check="overall"`; latest private probe observation, 1 ready or 0 shutting down | `/_readiness` | -| `buzz_readiness_dependency_checks_total` | counter | `dependency`, typed bounded `outcome` | `/_status` | -| `buzz_readiness_check_duration_seconds` | histogram | `check` only | `/_status` | - -The two dependency families keep their `buzz_readiness_*` names for dashboard -continuity; their trigger moved from the 5s probe to `/_status`, so they now -sample only when an operator or a scheduled scrape requests that endpoint. - -The schema has a ceiling of 86 raw Prometheus series per pod: 2 probe reasons, -11 valid dependency/outcome pairs, 72 histogram series, and 1 gauge. Do not add -pod, ReplicaSet, version, rollout, error text, SQL, URL, tenant, user, +| `buzz_readiness_dependency_checks_total` | counter | `dependency`, typed bounded `outcome` | dependency sampler | +| `buzz_readiness_check_duration_seconds` | histogram | `check` only | dependency sampler | +| `buzz_readiness_dependency_sample_age_seconds` | gauge | none; age of the cached report | dependency sampler | + +The three dependency families keep their `buzz_readiness_*` names for dashboard +continuity, but nothing about them is request-driven any more: the 30-second +sampler publishes them whether or not anyone reads `/_status`, so a quiet +endpoint no longer produces a flat dashboard during the outage it exists to +explain. + +`buzz_readiness_dependency_sample_age_seconds` follows the +`buzz_storage_sweep_age_seconds` convention. It is **absent until the first +report exists**, so absence means "not yet sampled", never "fresh". Each cycle +republishes it before evaluating, so in steady state it reads about one cadence +and grows whenever a cycle runs late. A sampler that stops advancing it leaves +the series frozen and then evicted by the exporter's gauge idle timeout — +alert on `absent()` or on a value well above the cadence. + +The schema has a ceiling of 87 raw Prometheus series per pod: 2 probe reasons, +11 valid dependency/outcome pairs, 72 histogram series, and 2 gauges. Do not +add pod, ReplicaSet, version, rollout, error text, SQL, URL, tenant, user, community, pubkey, header, query, or other request-controlled labels. A readiness probe records no dependency attempt or latency sample at all. -The gauge is not a monotonic lifecycle mirror: shutdown changes the +The readiness gauge is not a monotonic lifecycle mirror: shutdown changes the authoritative lifecycle flag, and the next private readiness probe observes and publishes that state. diff --git a/docs/deployment-identity.md b/docs/deployment-identity.md index ad356eb534c..f5bc8710d10 100644 --- a/docs/deployment-identity.md +++ b/docs/deployment-identity.md @@ -49,6 +49,9 @@ The relay health listener exposes intrinsic build identity at `/_status`: "url": "https://github.com/block/buzz/actions/runs//attempts/" }, "dependencies": { + "sample": "fresh", + "sample_interval_seconds": 30, + "sample_age_seconds": 12, "postgres": true, "redis": true, "deletion_catalog": true, @@ -60,8 +63,13 @@ The relay health listener exposes intrinsic build identity at `/_status`: Non-CI builds report stable `unknown` or `local` fallback values instead of claiming provenance they do not have. -`dependencies` is a diagnostic snapshot of shared-dependency health, evaluated -per request with a two-second budget. `/_readiness` does not consult it — see +`dependencies` is a cached diagnostic snapshot of shared-dependency health. A +per-pod background loop evaluates the dependencies every 30 seconds; the +endpoint only reads the latest report and never contacts a dependency itself, +so polling it costs nothing. `sample` is always present and reports whether +that cached verdict is `fresh`, `stale`, or `not_yet_sampled` — before the +first cycle completes the health fields are absent rather than defaulted. +`/_readiness` does not consult any of this — see [the readiness contract](../deploy/charts/buzz/README.md#readiness-contract) — so this endpoint must never be wired to a Kubernetes probe. From a658363bd712b6546a26f087b2e59efc418d8ca3 Mon Sep 17 00:00:00 2001 From: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Date: Wed, 16 Sep 2026 14:50:45 +0000 Subject: [PATCH 07/17] refactor(relay): drop the dependency sample-age gauge MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Freshness does not need a series of its own. The dependency outcome and duration families stop receiving samples the moment the per-pod sampler stops, and the Datadog monitors alert on that no-data gap — so an age gauge would only add a series that the very loop whose absence it is meant to report has to keep advancing. A wedged sampler would freeze it at its last value and read as permanently fresh. Per-report freshness stays where a human reads it: `/_status` keeps its `sample`, `sample_age_seconds`, and `sample_interval_seconds` fields and still distinguishes not-yet-sampled from fresh from stale. The sampler cadence, single in-flight evaluation, and cached-read `/_status` are unchanged. Drops the readiness series ceiling from 87 to 86. Co-Authored-By: Claude Opus 5 Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Signed-off-by: tornquist --- crates/buzz-relay/src/metrics.rs | 5 --- crates/buzz-relay/src/readiness.rs | 72 +++--------------------------- crates/buzz-relay/src/router.rs | 15 +------ deploy/charts/buzz/README.md | 23 +++++----- 4 files changed, 19 insertions(+), 96 deletions(-) diff --git a/crates/buzz-relay/src/metrics.rs b/crates/buzz-relay/src/metrics.rs index 40d7ac9bf87..02c1a0c1eb8 100644 --- a/crates/buzz-relay/src/metrics.rs +++ b/crates/buzz-relay/src/metrics.rs @@ -332,11 +332,6 @@ pub(crate) fn describe_readiness_metrics() { "buzz_readiness_state", "Latest private readiness-probe observation, where 1 is ready and 0 is shutting down" ); - metrics::describe_gauge!( - "buzz_readiness_dependency_sample_age_seconds", - metrics::Unit::Seconds, - "Age of the cached /_status dependency report, absent until the first sample completes" - ); } /// Register the bounded community-admission contract. diff --git a/crates/buzz-relay/src/readiness.rs b/crates/buzz-relay/src/readiness.rs index 3b796519ebc..7c368316b5d 100644 --- a/crates/buzz-relay/src/readiness.rs +++ b/crates/buzz-relay/src/readiness.rs @@ -55,9 +55,8 @@ pub(crate) const READINESS_REASON_LABELS: [&str; 2] = ["ready", "shutting_down"] /// - 11 valid dependency/outcome pairs (Postgres 5, Redis 3, catalog 3) /// - 4 histograms x (15 configured buckets + `+Inf` + count + sum) = 72 /// - 1 overall readiness gauge -/// - 1 dependency-sample age gauge #[cfg(test)] -pub(crate) const READINESS_RAW_SERIES_PER_POD: usize = 2 + 11 + (4 * 18) + 1 + 1; +pub(crate) const READINESS_RAW_SERIES_PER_POD: usize = 2 + 11 + (4 * 18) + 1; /// Terminal outcome of one readiness probe. #[derive(Debug, Clone, Copy, PartialEq, Eq)] @@ -459,11 +458,11 @@ impl DependencyDiagnostics { /// Runs one bounded evaluation, publishes its telemetry, and replaces the /// cached report. /// - /// The age gauge is published first, while the cache still holds the report - /// this cycle is about to replace — that is the age a scrape would have - /// read, and it grows whenever a cycle runs late. + /// Freshness is not published as its own series: the dependency outcome and + /// duration families stop receiving samples the moment this loop stops, and + /// the monitors alert on that no-data gap. A separate age gauge would have + /// to be advanced by the very loop whose absence it is meant to report. pub(crate) async fn sample(&self, db: &Db, redis_pool: &deadpool_redis::Pool) { - record_dependency_sample_age(self.snapshot()); let report = self.evaluator.evaluate(db, redis_pool).await; record_dependency_report(&report); let sample = DependencySample { @@ -539,15 +538,6 @@ fn record_dependency_report(report: &DependencyReport) { ); } -/// Publishes the age of the cached report, following the -/// `buzz_storage_sweep_age_seconds` convention: absent until a report exists, -/// so absence means "not yet sampled" rather than "fresh". -fn record_dependency_sample_age(snapshot: DependencySnapshot) { - if let DependencySnapshot::Sampled { age, .. } = snapshot { - metrics::gauge!("buzz_readiness_dependency_sample_age_seconds").set(age.as_secs_f64()); - } -} - fn record_dependency_attempt(dependency: &'static str, outcome: &'static str, duration: Duration) { metrics::counter!( "buzz_readiness_dependency_checks_total", @@ -684,7 +674,7 @@ mod tests { .map(DeletionCatalogOutcome::label), ["success", "operation_timeout", "operation_error"] ); - assert_eq!(READINESS_RAW_SERIES_PER_POD, 87); + assert_eq!(READINESS_RAW_SERIES_PER_POD, 86); } #[test] @@ -850,56 +840,6 @@ mod tests { assert!(stale, "a report that outlived two cadences missed a cycle"); } - fn sample_age_gauge(snapshot: &Snapshot) -> Option { - exact_metric( - snapshot, - "buzz_readiness_dependency_sample_age_seconds", - &[], - ) - .map(|value| { - let DebugValue::Gauge(value) = value else { - panic!("sample age must be a gauge"); - }; - value.into_inner() - }) - } - - /// The scrape-side half of the same question. Following - /// `buzz_storage_sweep_age_seconds`, the gauge is absent until a report - /// exists and then carries the age of the cached report, so a sampler that - /// stops advancing it is visible without reading `/_status` at all. - #[test] - fn the_sample_age_gauge_is_absent_until_a_report_exists_then_carries_its_age() { - let runtime = tokio::runtime::Builder::new_current_thread() - .enable_all() - .start_paused(true) - .build() - .expect("paused current-thread runtime"); - let recorder = DebuggingRecorder::new(); - let snapshotter = recorder.snapshotter(); - - metrics::with_local_recorder(&recorder, || { - runtime.block_on(async { - let (db, redis_pool) = unreachable_dependencies(); - let diagnostics = ready_diagnostics(); - - diagnostics.sample(&db, &redis_pool).await; - assert_eq!( - sample_age_gauge(&snapshotter.snapshot().into_vec()), - None, - "the first cycle has no prior report whose age it could publish" - ); - - tokio::time::advance(DEPENDENCY_SAMPLE_INTERVAL).await; - diagnostics.sample(&db, &redis_pool).await; - assert_eq!( - sample_age_gauge(&snapshotter.snapshot().into_vec()), - Some(DEPENDENCY_SAMPLE_INTERVAL.as_secs_f64()) - ); - }); - }); - } - #[test] fn readiness_reason_labels_are_the_closed_lifecycle_set() { assert_eq!( diff --git a/crates/buzz-relay/src/router.rs b/crates/buzz-relay/src/router.rs index 6d5a32580c3..80a32b57e47 100644 --- a/crates/buzz-relay/src/router.rs +++ b/crates/buzz-relay/src/router.rs @@ -1529,19 +1529,6 @@ mod tests { 0.0 ); assert!(!final_scrape.contains("sensitive-sql-or-url")); - // Freshness is part of the frozen contract: one unlabelled - // gauge, published from the second cycle on, so a stalled - // sampler is visible from a scrape alone. - assert!(final_scrape - .contains("# TYPE buzz_readiness_dependency_sample_age_seconds gauge")); - assert_eq!( - final_scrape - .lines() - .filter(|line| line - .starts_with("buzz_readiness_dependency_sample_age_seconds")) - .count(), - 1 - ); let exported_reasons = final_scrape .lines() @@ -1551,7 +1538,7 @@ mod tests { assert_eq!( readiness_metric_lines(&final_scrape).len(), readiness::READINESS_RAW_SERIES_PER_POD, - "readiness series contract must stay at or below its 87-series cap" + "readiness series contract must stay at or below its 86-series cap" ); }); }); diff --git a/deploy/charts/buzz/README.md b/deploy/charts/buzz/README.md index 3e5aea4fbd3..208147f825e 100644 --- a/deploy/charts/buzz/README.md +++ b/deploy/charts/buzz/README.md @@ -174,7 +174,6 @@ listener returns the same lifecycle answer but does not change these metrics. | `buzz_readiness_state` | gauge | `check="overall"`; latest private probe observation, 1 ready or 0 shutting down | `/_readiness` | | `buzz_readiness_dependency_checks_total` | counter | `dependency`, typed bounded `outcome` | dependency sampler | | `buzz_readiness_check_duration_seconds` | histogram | `check` only | dependency sampler | -| `buzz_readiness_dependency_sample_age_seconds` | gauge | none; age of the cached report | dependency sampler | The three dependency families keep their `buzz_readiness_*` names for dashboard continuity, but nothing about them is request-driven any more: the 30-second @@ -182,16 +181,18 @@ sampler publishes them whether or not anyone reads `/_status`, so a quiet endpoint no longer produces a flat dashboard during the outage it exists to explain. -`buzz_readiness_dependency_sample_age_seconds` follows the -`buzz_storage_sweep_age_seconds` convention. It is **absent until the first -report exists**, so absence means "not yet sampled", never "fresh". Each cycle -republishes it before evaluating, so in steady state it reads about one cadence -and grows whenever a cycle runs late. A sampler that stops advancing it leaves -the series frozen and then evicted by the exporter's gauge idle timeout — -alert on `absent()` or on a value well above the cadence. - -The schema has a ceiling of 87 raw Prometheus series per pod: 2 probe reasons, -11 valid dependency/outcome pairs, 72 histogram series, and 2 gauges. Do not +Freshness has no series of its own. The dependency outcome and duration +families stop receiving samples the moment the loop stops, so **alert on +no-data** for `buzz_readiness_dependency_checks_total` and +`buzz_readiness_check_duration_seconds` (Datadog monitors do this already). An +age gauge would have to be advanced by the very loop whose absence it is meant +to report, so a wedged sampler would freeze it at its last value and read as +permanently fresh. Per-report freshness stays where a human reads it: the +`sample`, `sample_age_seconds`, and `sample_interval_seconds` fields of +`/_status` above. + +The schema has a ceiling of 86 raw Prometheus series per pod: 2 probe reasons, +11 valid dependency/outcome pairs, 72 histogram series, and 1 gauge. Do not add pod, ReplicaSet, version, rollout, error text, SQL, URL, tenant, user, community, pubkey, header, query, or other request-controlled labels. A readiness probe records no dependency attempt or latency sample at all. From 9d5e04e0c2654577ff777df83dcc90da8c3b3fdf Mon Sep 17 00:00:00 2001 From: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Date: Wed, 16 Sep 2026 14:50:57 +0000 Subject: [PATCH 08/17] test(relay): bind the dependency sampler to real startup MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Startup is the only owner of dependency evaluation: `/_status` reads the cache, a readiness probe records no dependency attempt, and no request path may start a check. So if `main` stops spawning the sampler, the pod evaluates Postgres, Redis, and the deletion catalog exactly never — the dependency families stay absent from its scrape and `/_status` answers `not_yet_sampled` for the pod's whole life. No in-process test can fail on that, because every one of them drives `sample` itself. Adds one case to the existing real-binary boot harness: boot the relay against the PostgreSQL lane's Postgres and Redis, then read only the relay's own `/metrics` — no probe, no `/_status`, nothing that could evaluate a dependency on the test's behalf. Verified falsifiable by deleting the spawn from `main` and watching it fail. `wait_for_relay_metrics` is generalized to poll for a named metric family so the wait stays bounded by the harness deadline rather than a sleep. Co-Authored-By: Claude Opus 5 Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Signed-off-by: tornquist --- crates/buzz-relay/tests/boot_lifecycle.rs | 77 +++++++++++++++++++++-- 1 file changed, 73 insertions(+), 4 deletions(-) diff --git a/crates/buzz-relay/tests/boot_lifecycle.rs b/crates/buzz-relay/tests/boot_lifecycle.rs index 10e2c2e4f54..2fc7a10d4f7 100644 --- a/crates/buzz-relay/tests/boot_lifecycle.rs +++ b/crates/buzz-relay/tests/boot_lifecycle.rs @@ -17,6 +17,8 @@ const VALID_RELAY_PRIVATE_KEY: &str = "0000000000000000000000000000000000000000000000000000000000000001"; const CHILD_TIMEOUT: Duration = Duration::from_secs(10); const MAX_CAPTURE_BYTES: u64 = 1024 * 1024; +/// Bound on every wait for the relay to export a metric family. +const METRICS_SCRAPE_DEADLINE: Duration = Duration::from_secs(8); struct RelayProcess { child: Option, @@ -158,20 +160,27 @@ fn scrape_metrics(port: u16) -> std::io::Result { } fn wait_for_relay_metrics(process: &mut RelayProcess, port: u16) -> String { - let deadline = Instant::now() + Duration::from_secs(8); + wait_for_scraped_metric(process, port, "buzz_audit_enabled") +} + +/// Polls the relay's own `/metrics` until `needle` appears, bounded by +/// [`METRICS_SCRAPE_DEADLINE`]. A relay that exits first is a failure, not a +/// timeout, so the panic names the real cause. +fn wait_for_scraped_metric(process: &mut RelayProcess, port: u16, needle: &str) -> String { + let deadline = Instant::now() + METRICS_SCRAPE_DEADLINE; loop { assert!( process.try_wait().is_none(), - "relay exited before its metrics endpoint became usable" + "relay exited before exporting {needle}" ); if let Ok(response) = scrape_metrics(port) { - if response.contains("buzz_audit_enabled") { + if response.contains(needle) { return response; } } assert!( Instant::now() < deadline, - "relay metrics did not become scrapeable within 8s" + "relay did not export {needle} within {METRICS_SCRAPE_DEADLINE:?}" ); thread::sleep(Duration::from_millis(20)); } @@ -763,4 +772,64 @@ mod postgres_tests { "the health port must never have been bound" ); } + + /// Startup is the only owner of dependency evaluation. `/_status` just reads + /// the cache, a readiness probe records no dependency attempt at all, and no + /// request path may start a check — so if `main` stops spawning the sampler, + /// this pod evaluates Postgres, Redis, and the deletion catalog exactly + /// never: the dependency families stay absent from its scrape and `/_status` + /// answers `not_yet_sampled` for the pod's whole life. + /// + /// No in-process test can fail on that, because each one drives `sample` + /// itself. This one boots the real binary against real dependencies and + /// reads only the relay's own `/metrics` — no probe, no `/_status`, nothing + /// that could evaluate a dependency on the test's behalf. The first tick + /// fires immediately, so the wait is bounded by + /// [`METRICS_SCRAPE_DEADLINE`] and never a fixed sleep. + #[test] + #[ignore = "requires PostgreSQL"] + fn startup_owns_the_dependency_sampler() { + let database_url = std::env::var("DATABASE_URL") + .expect("postgres lane provides DATABASE_URL for each test process"); + let redis_url = std::env::var("REDIS_URL") + .expect("the postgres lane runs alongside Redis and exports REDIS_URL"); + let metrics_port = reserve_closed_port(); + let metrics_port_value = metrics_port.to_string(); + let health_port_value = reserve_closed_port().to_string(); + let bind_addr = format!("127.0.0.1:{}", reserve_closed_port()); + + let mut process = RelayProcess::spawn(&[ + ("BUZZ_RELAY_PRIVATE_KEY", VALID_RELAY_PRIVATE_KEY), + ("BUZZ_METRICS_PORT", &metrics_port_value), + ("BUZZ_HEALTH_PORT", &health_port_value), + ("BUZZ_BIND_ADDR", &bind_addr), + ("DATABASE_URL", &database_url), + ("REDIS_URL", &redis_url), + ("BUZZ_GIT_CONFORMANCE_PROBE", "false"), + ]); + let scrape = wait_for_scraped_metric( + &mut process, + metrics_port, + "buzz_readiness_dependency_checks_total{", + ); + let output = process.terminate(); + let logs = format!( + "{}{}", + String::from_utf8_lossy(&output.stdout), + String::from_utf8_lossy(&output.stderr) + ); + + assert!( + scrape.contains("buzz_readiness_check_duration_seconds"), + "a completed evaluation must publish its latency too: {scrape}" + ); + assert!( + !scrape.contains("buzz_readiness_checks_total{"), + "no readiness probe was sent, so the sampler alone produced this: {scrape}" + ); + assert!( + logs.contains("Health probe listener started"), + "the sampler must be owned by a relay that finished booting: {logs}" + ); + } } From 28de4b609efff14c474b69f4510fc32e0e1cf539 Mon Sep 17 00:00:00 2001 From: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Date: Wed, 16 Sep 2026 15:28:02 +0000 Subject: [PATCH 09/17] feat(relay): publish the dependency sample completion timestamp MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The dependency outcome counters and latency histograms are cumulative, so a stopped sampler leaves their last values being scraped indefinitely: the series stay present and flat, and no-data never fires. Freshness needs a series of its own, and it has to be a timestamp rather than an age — a gauge carrying the age would have to be advanced by the very loop whose absence it is meant to report, so a wedged sampler would freeze it at its last value and read as permanently fresh. `buzz_readiness_dependency_sample_completed_timestamp_seconds` carries the Unix time the cached report completed. `sample` writes it last, once the cache already serves that report, and nothing else writes it — the age is computed by the query (`time() - `), with no server-side aging loop. Absent until the first sample completes, so absence means "not yet sampled" rather than "fresh". `/_status` keeps its own cached `sample_age_seconds` and fresh/stale verdict unchanged. The chart README documents the query, the `absent()` case, and why no-data on the counters and histograms does not detect a stopped sampler. Readiness series ceiling 86 -> 87. Co-Authored-By: Claude Opus 5 Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Signed-off-by: tornquist --- crates/buzz-relay/src/metrics.rs | 5 + crates/buzz-relay/src/readiness.rs | 133 ++++++++++++++++++++-- crates/buzz-relay/src/router.rs | 18 ++- crates/buzz-relay/tests/boot_lifecycle.rs | 11 +- deploy/charts/buzz/README.md | 40 +++++-- 5 files changed, 186 insertions(+), 21 deletions(-) diff --git a/crates/buzz-relay/src/metrics.rs b/crates/buzz-relay/src/metrics.rs index 02c1a0c1eb8..c23442c5ac9 100644 --- a/crates/buzz-relay/src/metrics.rs +++ b/crates/buzz-relay/src/metrics.rs @@ -332,6 +332,11 @@ pub(crate) fn describe_readiness_metrics() { "buzz_readiness_state", "Latest private readiness-probe observation, where 1 is ready and 0 is shutting down" ); + metrics::describe_gauge!( + "buzz_readiness_dependency_sample_completed_timestamp_seconds", + metrics::Unit::Seconds, + "Unix time the cached /_status dependency report completed, absent until the first sample completes" + ); } /// Register the bounded community-admission contract. diff --git a/crates/buzz-relay/src/readiness.rs b/crates/buzz-relay/src/readiness.rs index 7c368316b5d..3330fb06d4d 100644 --- a/crates/buzz-relay/src/readiness.rs +++ b/crates/buzz-relay/src/readiness.rs @@ -17,7 +17,7 @@ use std::future::Future; use std::sync::{Arc, Mutex, PoisonError}; -use std::time::Duration; +use std::time::{Duration, SystemTime}; use buzz_db::{Db, DbError, DbReadinessOutcome}; use tokio::time::Instant; @@ -55,8 +55,9 @@ pub(crate) const READINESS_REASON_LABELS: [&str; 2] = ["ready", "shutting_down"] /// - 11 valid dependency/outcome pairs (Postgres 5, Redis 3, catalog 3) /// - 4 histograms x (15 configured buckets + `+Inf` + count + sum) = 72 /// - 1 overall readiness gauge +/// - 1 sample-completion timestamp gauge #[cfg(test)] -pub(crate) const READINESS_RAW_SERIES_PER_POD: usize = 2 + 11 + (4 * 18) + 1; +pub(crate) const READINESS_RAW_SERIES_PER_POD: usize = 2 + 11 + (4 * 18) + 1 + 1; /// Terminal outcome of one readiness probe. #[derive(Debug, Clone, Copy, PartialEq, Eq)] @@ -458,10 +459,9 @@ impl DependencyDiagnostics { /// Runs one bounded evaluation, publishes its telemetry, and replaces the /// cached report. /// - /// Freshness is not published as its own series: the dependency outcome and - /// duration families stop receiving samples the moment this loop stops, and - /// the monitors alert on that no-data gap. A separate age gauge would have - /// to be advanced by the very loop whose absence it is meant to report. + /// The completion timestamp is written last, once the cache already serves + /// this report, so the gauge can never describe a sample `/_status` is not + /// yet answering with. pub(crate) async fn sample(&self, db: &Db, redis_pool: &deadpool_redis::Pool) { let report = self.evaluator.evaluate(db, redis_pool).await; record_dependency_report(&report); @@ -470,6 +470,7 @@ impl DependencyDiagnostics { observed_at: Instant::now(), }; *self.latest.lock().unwrap_or_else(PoisonError::into_inner) = Some(sample); + record_dependency_sample_completion(SystemTime::now()); } /// The latest completed evaluation with its age. Starts no dependency work. @@ -538,6 +539,25 @@ fn record_dependency_report(report: &DependencyReport) { ); } +/// Publishes the Unix time the cached report completed. +/// +/// A completion timestamp rather than an age, because age then belongs to the +/// query — `time() - buzz_readiness_dependency_sample_completed_timestamp_seconds` +/// — and grows on its own while this pod is wedged. A gauge carrying the age +/// needs a writer to advance it, so the one failure it most needs to expose, a +/// sampler that stopped running, is the one that would freeze it at its last +/// value and read as permanently fresh. Nothing but a completed sample writes +/// this, which also keeps the `buzz_storage_sweep_age_seconds` convention that +/// absence means "not yet sampled" rather than "fresh". +fn record_dependency_sample_completion(completed_at: SystemTime) { + let epoch_seconds = completed_at + .duration_since(SystemTime::UNIX_EPOCH) + .unwrap_or_default() + .as_secs_f64(); + metrics::gauge!("buzz_readiness_dependency_sample_completed_timestamp_seconds") + .set(epoch_seconds); +} + fn record_dependency_attempt(dependency: &'static str, outcome: &'static str, duration: Duration) { metrics::counter!( "buzz_readiness_dependency_checks_total", @@ -674,7 +694,7 @@ mod tests { .map(DeletionCatalogOutcome::label), ["success", "operation_timeout", "operation_error"] ); - assert_eq!(READINESS_RAW_SERIES_PER_POD, 86); + assert_eq!(READINESS_RAW_SERIES_PER_POD, 87); } #[test] @@ -840,6 +860,105 @@ mod tests { assert!(stale, "a report that outlived two cadences missed a cycle"); } + /// The completion timestamp written since the previous snapshot, if any. + /// + /// `Snapshotter::snapshot` drains, so a window in which nothing wrote the + /// gauge either omits the key entirely or, once registered, replays as + /// `0.0`. Zero is not a time any sample could have completed at, so folding + /// it into `None` keeps "nobody wrote this in that window" expressible — + /// the property a completion timestamp must have and an age cannot. + fn sample_completion_gauge(snapshot: &Snapshot) -> Option { + exact_metric( + snapshot, + "buzz_readiness_dependency_sample_completed_timestamp_seconds", + &[], + ) + .map(|value| { + let DebugValue::Gauge(value) = value else { + panic!("the sample completion timestamp must be a gauge"); + }; + value.into_inner() + }) + .filter(|written| *written != 0.0) + } + + fn epoch_seconds_now() -> f64 { + std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .expect("the system clock is after the Unix epoch") + .as_secs_f64() + } + + /// The scrape-side half of the same question. Freshness is published as the + /// Unix time the cached report completed, written only by a completed + /// sample, so the age belongs to the query + /// (`time() - buzz_readiness_dependency_sample_completed_timestamp_seconds`) + /// and grows on its own while this pod is wedged. A gauge carrying the age + /// instead would need a writer to advance it, so the one failure it most + /// needs to expose — a sampler that stopped — is the one that would freeze + /// it at its last value and read as permanently fresh. + #[test] + fn the_completion_timestamp_gauge_is_written_once_per_completed_sample() { + let runtime = tokio::runtime::Builder::new_current_thread() + .enable_all() + .start_paused(true) + .build() + .expect("paused current-thread runtime"); + let recorder = DebuggingRecorder::new(); + let snapshotter = recorder.snapshotter(); + + metrics::with_local_recorder(&recorder, || { + runtime.block_on(async { + let (db, redis_pool) = unreachable_dependencies(); + let diagnostics = ready_diagnostics(); + + assert_eq!( + sample_completion_gauge(&snapshotter.snapshot().into_vec()), + None, + "absence is the not-yet-sampled signal, not a fresh zero" + ); + + let before_first = epoch_seconds_now(); + diagnostics.sample(&db, &redis_pool).await; + let after_first = epoch_seconds_now(); + let first = sample_completion_gauge(&snapshotter.snapshot().into_vec()) + .expect("a completed sample must publish when it completed"); + assert!( + (before_first..=after_first).contains(&first), + "{first} must be the wall time the sample completed, \ + not an age, and not a stale reading" + ); + + // Paused time: no task, timer, or aging loop can run here. + tokio::time::advance(DEPENDENCY_SAMPLE_STALE_AFTER + Duration::from_secs(1)).await; + assert_eq!( + sample_completion_gauge(&snapshotter.snapshot().into_vec()), + None, + "only a completed sample may write the gauge, so the age a \ + query derives from it grows with no server-side writer" + ); + assert!( + sampled(diagnostics.snapshot()).1, + "the cached `/_status` age reports the same report as stale" + ); + + let before_second = epoch_seconds_now(); + diagnostics.sample(&db, &redis_pool).await; + let after_second = epoch_seconds_now(); + let second = sample_completion_gauge(&snapshotter.snapshot().into_vec()) + .expect("the next completed sample republishes the timestamp"); + assert!( + (before_second..=after_second).contains(&second) && second >= first, + "{second} must re-anchor to the second completion, after {first}" + ); + assert!( + !sampled(diagnostics.snapshot()).1, + "a fresh completion clears staleness" + ); + }); + }); + } + #[test] fn readiness_reason_labels_are_the_closed_lifecycle_set() { assert_eq!( diff --git a/crates/buzz-relay/src/router.rs b/crates/buzz-relay/src/router.rs index 80a32b57e47..cd9895d286d 100644 --- a/crates/buzz-relay/src/router.rs +++ b/crates/buzz-relay/src/router.rs @@ -1529,6 +1529,22 @@ mod tests { 0.0 ); assert!(!final_scrape.contains("sensitive-sql-or-url")); + // Freshness is part of the frozen contract: one unlabelled + // gauge carrying when the cached report completed, so + // `time() - ` ages a stalled sampler out from a scrape + // alone. + assert!(final_scrape.contains( + "# TYPE buzz_readiness_dependency_sample_completed_timestamp_seconds gauge" + )); + assert_eq!( + final_scrape + .lines() + .filter(|line| line.starts_with( + "buzz_readiness_dependency_sample_completed_timestamp_seconds" + )) + .count(), + 1 + ); let exported_reasons = final_scrape .lines() @@ -1538,7 +1554,7 @@ mod tests { assert_eq!( readiness_metric_lines(&final_scrape).len(), readiness::READINESS_RAW_SERIES_PER_POD, - "readiness series contract must stay at or below its 86-series cap" + "readiness series contract must stay at or below its 87-series cap" ); }); }); diff --git a/crates/buzz-relay/tests/boot_lifecycle.rs b/crates/buzz-relay/tests/boot_lifecycle.rs index 2fc7a10d4f7..1d43fc3236e 100644 --- a/crates/buzz-relay/tests/boot_lifecycle.rs +++ b/crates/buzz-relay/tests/boot_lifecycle.rs @@ -786,6 +786,11 @@ mod postgres_tests { /// that could evaluate a dependency on the test's behalf. The first tick /// fires immediately, so the wait is bounded by /// [`METRICS_SCRAPE_DEADLINE`] and never a fixed sleep. + /// + /// The completion-timestamp gauge is the needle because `sample` writes it + /// last, after the cache already serves the report: observing it proves the + /// whole cycle ran, with no window where the counters have landed but the + /// timestamp has not. #[test] #[ignore = "requires PostgreSQL"] fn startup_owns_the_dependency_sampler() { @@ -810,7 +815,7 @@ mod postgres_tests { let scrape = wait_for_scraped_metric( &mut process, metrics_port, - "buzz_readiness_dependency_checks_total{", + "buzz_readiness_dependency_sample_completed_timestamp_seconds", ); let output = process.terminate(); let logs = format!( @@ -819,6 +824,10 @@ mod postgres_tests { String::from_utf8_lossy(&output.stderr) ); + assert!( + scrape.contains("buzz_readiness_dependency_checks_total{"), + "the same cycle must publish its per-dependency outcomes: {scrape}" + ); assert!( scrape.contains("buzz_readiness_check_duration_seconds"), "a completed evaluation must publish its latency too: {scrape}" diff --git a/deploy/charts/buzz/README.md b/deploy/charts/buzz/README.md index 208147f825e..87c70dba693 100644 --- a/deploy/charts/buzz/README.md +++ b/deploy/charts/buzz/README.md @@ -174,6 +174,7 @@ listener returns the same lifecycle answer but does not change these metrics. | `buzz_readiness_state` | gauge | `check="overall"`; latest private probe observation, 1 ready or 0 shutting down | `/_readiness` | | `buzz_readiness_dependency_checks_total` | counter | `dependency`, typed bounded `outcome` | dependency sampler | | `buzz_readiness_check_duration_seconds` | histogram | `check` only | dependency sampler | +| `buzz_readiness_dependency_sample_completed_timestamp_seconds` | gauge | none; Unix time the cached report completed | dependency sampler | The three dependency families keep their `buzz_readiness_*` names for dashboard continuity, but nothing about them is request-driven any more: the 30-second @@ -181,18 +182,33 @@ sampler publishes them whether or not anyone reads `/_status`, so a quiet endpoint no longer produces a flat dashboard during the outage it exists to explain. -Freshness has no series of its own. The dependency outcome and duration -families stop receiving samples the moment the loop stops, so **alert on -no-data** for `buzz_readiness_dependency_checks_total` and -`buzz_readiness_check_duration_seconds` (Datadog monitors do this already). An -age gauge would have to be advanced by the very loop whose absence it is meant -to report, so a wedged sampler would freeze it at its last value and read as -permanently fresh. Per-report freshness stays where a human reads it: the -`sample`, `sample_age_seconds`, and `sample_interval_seconds` fields of -`/_status` above. - -The schema has a ceiling of 86 raw Prometheus series per pod: 2 probe reasons, -11 valid dependency/outcome pairs, 72 histogram series, and 1 gauge. Do not +`buzz_readiness_dependency_sample_completed_timestamp_seconds` carries **when +the cached report completed**, in Unix seconds, and is written only by a +completed sample — nothing ages it in the background. The age is therefore a +property of the query, not of a server-side loop: + +```promql +time() - buzz_readiness_dependency_sample_completed_timestamp_seconds > 60 +``` + +That expression grows on its own while a pod is wedged, which is the point of a +timestamp rather than an age: a gauge carrying the age would have to be advanced +by the very loop whose absence it is meant to report, so a stopped sampler would +freeze it at its last value and read as permanently fresh. `60` is two cadences, +the same threshold `/_status` uses to call a report `stale`. + +Do not alert on no-data for `buzz_readiness_dependency_checks_total` or +`buzz_readiness_check_duration_seconds`. Both are cumulative: a stopped sampler +leaves their last values being scraped indefinitely, so the series stay present +and flat. The timestamp gauge is the only series whose derived age moves when +sampling stops. Following the `buzz_storage_sweep_age_seconds` convention, that +gauge is **absent until the first sample completes**, so absence means "not yet +sampled", never "fresh" — alert on `absent()` as well. Per-report freshness for +a human reading a single pod stays on the `sample`, `sample_age_seconds`, and +`sample_interval_seconds` fields of `/_status` above. + +The schema has a ceiling of 87 raw Prometheus series per pod: 2 probe reasons, +11 valid dependency/outcome pairs, 72 histogram series, and 2 gauges. Do not add pod, ReplicaSet, version, rollout, error text, SQL, URL, tenant, user, community, pubkey, header, query, or other request-controlled labels. A readiness probe records no dependency attempt or latency sample at all. From d411cf63b6793b2f76fa391da10543c3b5d1d1ba Mon Sep 17 00:00:00 2001 From: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Date: Wed, 16 Sep 2026 20:14:14 +0000 Subject: [PATCH 10/17] docs(relay): scope the sample-timestamp gauge to the server contract The chart README prescribed a PromQL recipe (`time() - > 60`) and `absent()`/no-data alerting for the new completion-timestamp gauge. Those are provider-specific and were never validated against the deployment's actual monitoring provider, where neither `time()` nor `absent()` exists in the metric-monitor query grammar and no-data semantics differ. Documenting them as the alerting contract would have sent an operator down a path that does not work. Keeps the factual server-side contract: the gauge is the Unix time the cached report completed, written once per completed sample right after the cache is replaced, by nothing else; it stands still when sampling stops, so elapsed time is whatever the reader computes; and it is not emitted until the first sample completes. Monitor query, thresholds, and per-pod tag grouping belong with the deployment's monitor configuration, which this repo does not own. Keeps the accurate note that the dependency counters and latency histogram are cumulative, so a stopped sampler leaves their series present and flat. Documentation only. No Rust or test changes. Co-Authored-By: Claude Opus 5 Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Signed-off-by: tornquist --- deploy/charts/buzz/README.md | 44 ++++++++++++++++++------------------ 1 file changed, 22 insertions(+), 22 deletions(-) diff --git a/deploy/charts/buzz/README.md b/deploy/charts/buzz/README.md index 87c70dba693..9adb3eae743 100644 --- a/deploy/charts/buzz/README.md +++ b/deploy/charts/buzz/README.md @@ -183,28 +183,28 @@ endpoint no longer produces a flat dashboard during the outage it exists to explain. `buzz_readiness_dependency_sample_completed_timestamp_seconds` carries **when -the cached report completed**, in Unix seconds, and is written only by a -completed sample — nothing ages it in the background. The age is therefore a -property of the query, not of a server-side loop: - -```promql -time() - buzz_readiness_dependency_sample_completed_timestamp_seconds > 60 -``` - -That expression grows on its own while a pod is wedged, which is the point of a -timestamp rather than an age: a gauge carrying the age would have to be advanced -by the very loop whose absence it is meant to report, so a stopped sampler would -freeze it at its last value and read as permanently fresh. `60` is two cadences, -the same threshold `/_status` uses to call a report `stale`. - -Do not alert on no-data for `buzz_readiness_dependency_checks_total` or -`buzz_readiness_check_duration_seconds`. Both are cumulative: a stopped sampler -leaves their last values being scraped indefinitely, so the series stay present -and flat. The timestamp gauge is the only series whose derived age moves when -sampling stops. Following the `buzz_storage_sweep_age_seconds` convention, that -gauge is **absent until the first sample completes**, so absence means "not yet -sampled", never "fresh" — alert on `absent()` as well. Per-report freshness for -a human reading a single pod stays on the `sample`, `sample_age_seconds`, and +the cached report completed**, in Unix seconds. The relay writes it once per +completed sample, immediately after the cache is replaced, and nothing else +writes it — there is no background loop that ages it. So the value stands still +when sampling stops, and the time elapsed since it was written is whatever the +reader computes at read time. + +Following the `buzz_storage_sweep_age_seconds` convention, the series is not +emitted until the first sample completes: its absence means "not yet sampled", +not "fresh". + +That is the whole server-side contract. Freshness alerting is built from this +gauge in the monitoring provider, and the monitor query, thresholds, and +per-pod tag grouping belong with the deployment's monitor configuration rather +than in this chart — they depend on the provider's query grammar and on the +tags its agent attaches, neither of which this repo owns. + +Two properties of the neighboring families are worth knowing when building +that alerting. `buzz_readiness_dependency_checks_total` and +`buzz_readiness_check_duration_seconds` are cumulative, so a sampler that stops +leaves their last values exported and scraped indefinitely: those series stay +present and flat rather than disappearing. And per-report freshness for a human +reading a single pod is already on the `sample`, `sample_age_seconds`, and `sample_interval_seconds` fields of `/_status` above. The schema has a ceiling of 87 raw Prometheus series per pod: 2 probe reasons, From 6817409c760ce6457f49482c08dac2d58c188359 Mon Sep 17 00:00:00 2001 From: tornquist Date: Thu, 24 Sep 2026 21:31:10 +0000 Subject: [PATCH 11/17] fix(relay): retain readiness completion timestamp metric across idle cleanup Signed-off-by: tornquist Co-authored-by: Amp Signed-off-by: tornquist --- crates/buzz-relay/src/metrics.rs | 15 ++++- crates/buzz-relay/src/readiness.rs | 101 +++++++++++++++++++++++------ crates/buzz-relay/src/router.rs | 6 +- deploy/charts/buzz/README.md | 6 +- 4 files changed, 100 insertions(+), 28 deletions(-) diff --git a/crates/buzz-relay/src/metrics.rs b/crates/buzz-relay/src/metrics.rs index c23442c5ac9..7d8b42ea853 100644 --- a/crates/buzz-relay/src/metrics.rs +++ b/crates/buzz-relay/src/metrics.rs @@ -332,9 +332,8 @@ pub(crate) fn describe_readiness_metrics() { "buzz_readiness_state", "Latest private readiness-probe observation, where 1 is ready and 0 is shutting down" ); - metrics::describe_gauge!( + metrics::describe_counter!( "buzz_readiness_dependency_sample_completed_timestamp_seconds", - metrics::Unit::Seconds, "Unix time the cached /_status dependency report completed, absent until the first sample completes" ); } @@ -561,7 +560,17 @@ pub(crate) fn readiness_test_recorder() -> ( metrics_exporter_prometheus::PrometheusRecorder, metrics_exporter_prometheus::PrometheusHandle, ) { - let recorder = configured_prometheus_builder(300).build_recorder(); + readiness_test_recorder_with_idle_timeout(300) +} + +#[cfg(test)] +pub(crate) fn readiness_test_recorder_with_idle_timeout( + gauge_idle_timeout_secs: u64, +) -> ( + metrics_exporter_prometheus::PrometheusRecorder, + metrics_exporter_prometheus::PrometheusHandle, +) { + let recorder = configured_prometheus_builder(gauge_idle_timeout_secs).build_recorder(); let handle = recorder.handle(); (recorder, handle) } diff --git a/crates/buzz-relay/src/readiness.rs b/crates/buzz-relay/src/readiness.rs index 3330fb06d4d..d193c3351f1 100644 --- a/crates/buzz-relay/src/readiness.rs +++ b/crates/buzz-relay/src/readiness.rs @@ -55,7 +55,7 @@ pub(crate) const READINESS_REASON_LABELS: [&str; 2] = ["ready", "shutting_down"] /// - 11 valid dependency/outcome pairs (Postgres 5, Redis 3, catalog 3) /// - 4 histograms x (15 configured buckets + `+Inf` + count + sum) = 72 /// - 1 overall readiness gauge -/// - 1 sample-completion timestamp gauge +/// - 1 sample-completion timestamp counter #[cfg(test)] pub(crate) const READINESS_RAW_SERIES_PER_POD: usize = 2 + 11 + (4 * 18) + 1 + 1; @@ -549,13 +549,16 @@ fn record_dependency_report(report: &DependencyReport) { /// value and read as permanently fresh. Nothing but a completed sample writes /// this, which also keeps the `buzz_storage_sweep_age_seconds` convention that /// absence means "not yet sampled" rather than "fresh". +/// +/// This is emitted as an absolute counter so the configured gauge-idle cleanup +/// cannot evict it between samples while scrapes continue. fn record_dependency_sample_completion(completed_at: SystemTime) { let epoch_seconds = completed_at .duration_since(SystemTime::UNIX_EPOCH) .unwrap_or_default() - .as_secs_f64(); - metrics::gauge!("buzz_readiness_dependency_sample_completed_timestamp_seconds") - .set(epoch_seconds); + .as_secs(); + metrics::counter!("buzz_readiness_dependency_sample_completed_timestamp_seconds") + .absolute(epoch_seconds); } fn record_dependency_attempt(dependency: &'static str, outcome: &'static str, duration: Duration) { @@ -863,30 +866,38 @@ mod tests { /// The completion timestamp written since the previous snapshot, if any. /// /// `Snapshotter::snapshot` drains, so a window in which nothing wrote the - /// gauge either omits the key entirely or, once registered, replays as - /// `0.0`. Zero is not a time any sample could have completed at, so folding + /// counter either omits the key entirely or, once registered, replays as + /// `0`. Zero is not a time any sample could have completed at, so folding /// it into `None` keeps "nobody wrote this in that window" expressible — /// the property a completion timestamp must have and an age cannot. - fn sample_completion_gauge(snapshot: &Snapshot) -> Option { + fn sample_completion_counter(snapshot: &Snapshot) -> Option { exact_metric( snapshot, "buzz_readiness_dependency_sample_completed_timestamp_seconds", &[], ) .map(|value| { - let DebugValue::Gauge(value) = value else { - panic!("the sample completion timestamp must be a gauge"); + let DebugValue::Counter(value) = value else { + panic!("the sample completion timestamp must be a counter"); }; - value.into_inner() + *value }) - .filter(|written| *written != 0.0) + .filter(|written| *written != 0) } - fn epoch_seconds_now() -> f64 { + fn epoch_seconds_now() -> u64 { std::time::SystemTime::now() .duration_since(std::time::UNIX_EPOCH) .expect("the system clock is after the Unix epoch") - .as_secs_f64() + .as_secs() + } + + fn sample_completion_metric_value_from_scrape(scrape: &str) -> Option { + scrape.lines().find_map(|line| { + line.strip_prefix("buzz_readiness_dependency_sample_completed_timestamp_seconds ") + .and_then(|value| value.parse::().ok()) + .map(|value| value as u64) + }) } /// The scrape-side half of the same question. Freshness is published as the @@ -898,7 +909,7 @@ mod tests { /// needs to expose — a sampler that stopped — is the one that would freeze /// it at its last value and read as permanently fresh. #[test] - fn the_completion_timestamp_gauge_is_written_once_per_completed_sample() { + fn the_completion_timestamp_counter_is_written_once_per_completed_sample() { let runtime = tokio::runtime::Builder::new_current_thread() .enable_all() .start_paused(true) @@ -913,7 +924,7 @@ mod tests { let diagnostics = ready_diagnostics(); assert_eq!( - sample_completion_gauge(&snapshotter.snapshot().into_vec()), + sample_completion_counter(&snapshotter.snapshot().into_vec()), None, "absence is the not-yet-sampled signal, not a fresh zero" ); @@ -921,7 +932,7 @@ mod tests { let before_first = epoch_seconds_now(); diagnostics.sample(&db, &redis_pool).await; let after_first = epoch_seconds_now(); - let first = sample_completion_gauge(&snapshotter.snapshot().into_vec()) + let first = sample_completion_counter(&snapshotter.snapshot().into_vec()) .expect("a completed sample must publish when it completed"); assert!( (before_first..=after_first).contains(&first), @@ -932,9 +943,9 @@ mod tests { // Paused time: no task, timer, or aging loop can run here. tokio::time::advance(DEPENDENCY_SAMPLE_STALE_AFTER + Duration::from_secs(1)).await; assert_eq!( - sample_completion_gauge(&snapshotter.snapshot().into_vec()), + sample_completion_counter(&snapshotter.snapshot().into_vec()), None, - "only a completed sample may write the gauge, so the age a \ + "only a completed sample may write the counter, so the age a \ query derives from it grows with no server-side writer" ); assert!( @@ -945,7 +956,7 @@ mod tests { let before_second = epoch_seconds_now(); diagnostics.sample(&db, &redis_pool).await; let after_second = epoch_seconds_now(); - let second = sample_completion_gauge(&snapshotter.snapshot().into_vec()) + let second = sample_completion_counter(&snapshotter.snapshot().into_vec()) .expect("the next completed sample republishes the timestamp"); assert!( (before_second..=after_second).contains(&second) && second >= first, @@ -959,6 +970,58 @@ mod tests { }); } + #[test] + fn scrape_retains_the_completion_timestamp_across_gauge_idle_timeout() { + let timeout = Duration::from_secs(1); + let (recorder, handle) = + crate::metrics::readiness_test_recorder_with_idle_timeout(timeout.as_secs()); + + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + None, + "absence before the first completion is the not-yet-sampled signal" + ); + + let first = 4_750_000_001_u64; + metrics::with_local_recorder(&recorder, || { + record_dependency_sample_completion( + SystemTime::UNIX_EPOCH + Duration::from_secs(4_750_000_001), + ); + }); + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + Some(first), + "a completed sample publishes its Unix completion time" + ); + + // Keep scraping while the configured idle timeout elapses; this metric must + // stay queryable so freshness checks keep working during a stalled + // sampler. + std::thread::sleep(timeout + Duration::from_millis(200)); + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + Some(first), + "completion time must remain exported after idle timeout" + ); + std::thread::sleep(Duration::from_millis(100)); + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + Some(first), + "continued scrapes must not age this metric out" + ); + + metrics::with_local_recorder(&recorder, || { + record_dependency_sample_completion( + SystemTime::UNIX_EPOCH + Duration::from_secs(4_750_000_005), + ); + }); + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + Some(4_750_000_005_u64), + "the next completed sample republished the newer completion epoch" + ); + } + #[test] fn readiness_reason_labels_are_the_closed_lifecycle_set() { assert_eq!( diff --git a/crates/buzz-relay/src/router.rs b/crates/buzz-relay/src/router.rs index cd9895d286d..d97dbdeecad 100644 --- a/crates/buzz-relay/src/router.rs +++ b/crates/buzz-relay/src/router.rs @@ -1530,11 +1530,11 @@ mod tests { ); assert!(!final_scrape.contains("sensitive-sql-or-url")); // Freshness is part of the frozen contract: one unlabelled - // gauge carrying when the cached report completed, so - // `time() - ` ages a stalled sampler out from a scrape + // counter carrying when the cached report completed, so + // `time() - ` ages a stalled sampler out from a scrape // alone. assert!(final_scrape.contains( - "# TYPE buzz_readiness_dependency_sample_completed_timestamp_seconds gauge" + "# TYPE buzz_readiness_dependency_sample_completed_timestamp_seconds counter" )); assert_eq!( final_scrape diff --git a/deploy/charts/buzz/README.md b/deploy/charts/buzz/README.md index 9adb3eae743..245eac25e34 100644 --- a/deploy/charts/buzz/README.md +++ b/deploy/charts/buzz/README.md @@ -174,7 +174,7 @@ listener returns the same lifecycle answer but does not change these metrics. | `buzz_readiness_state` | gauge | `check="overall"`; latest private probe observation, 1 ready or 0 shutting down | `/_readiness` | | `buzz_readiness_dependency_checks_total` | counter | `dependency`, typed bounded `outcome` | dependency sampler | | `buzz_readiness_check_duration_seconds` | histogram | `check` only | dependency sampler | -| `buzz_readiness_dependency_sample_completed_timestamp_seconds` | gauge | none; Unix time the cached report completed | dependency sampler | +| `buzz_readiness_dependency_sample_completed_timestamp_seconds` | counter | none; Unix time the cached report completed | dependency sampler | The three dependency families keep their `buzz_readiness_*` names for dashboard continuity, but nothing about them is request-driven any more: the 30-second @@ -194,7 +194,7 @@ emitted until the first sample completes: its absence means "not yet sampled", not "fresh". That is the whole server-side contract. Freshness alerting is built from this -gauge in the monitoring provider, and the monitor query, thresholds, and +counter in the monitoring provider, and the monitor query, thresholds, and per-pod tag grouping belong with the deployment's monitor configuration rather than in this chart — they depend on the provider's query grammar and on the tags its agent attaches, neither of which this repo owns. @@ -208,7 +208,7 @@ reading a single pod is already on the `sample`, `sample_age_seconds`, and `sample_interval_seconds` fields of `/_status` above. The schema has a ceiling of 87 raw Prometheus series per pod: 2 probe reasons, -11 valid dependency/outcome pairs, 72 histogram series, and 2 gauges. Do not +11 valid dependency/outcome pairs, 72 histogram series, and 1 gauge plus 1 completion-timestamp counter. Do not add pod, ReplicaSet, version, rollout, error text, SQL, URL, tenant, user, community, pubkey, header, query, or other request-controlled labels. A readiness probe records no dependency attempt or latency sample at all. From 382223aa9c3f704b7a79a66099cb50e8b10dbbc5 Mon Sep 17 00:00:00 2001 From: tornquist Date: Thu, 24 Sep 2026 21:31:16 +0000 Subject: [PATCH 12/17] test(ci): include relay readiness and router unit selectors Signed-off-by: tornquist Co-authored-by: Codex --- Justfile | 2 +- scripts/run-tests.sh | 15 ++++++++++++--- 2 files changed, 13 insertions(+), 4 deletions(-) diff --git a/Justfile b/Justfile index 8bc31ab21a6..6377b290db8 100644 --- a/Justfile +++ b/Justfile @@ -472,7 +472,7 @@ test-unit: # because they live in the binary target; the nested # `tests::postgres_tests::` stays in the PostgreSQL lane. cargo nextest run -p buzz-relay --lib --bin buzz-relay \ - -E 'test(/^api::admin::/) + test(/^handlers::channel_authz::/) + test(/^handlers::moderation_authz::/) + test(/^handlers::side_effects::tests::/) + test(/^storage_sweep::tests::/) + test(/^nip_fi_http::tests::/) + test(/^nip_fi_config::tests::/) + test(/^router::tests::/) + test(/^api::parse_query_tests::/) + test(/^api::git::transport::off_mode_precedence_tests::/) + (kind(bin) & (test(/^tests::/) + test(/^composition_tests::/)) - test(/^tests::postgres_tests::/))' + -E 'test(/^api::admin::/) + test(/^handlers::channel_authz::/) + test(/^handlers::moderation_authz::/) + test(/^handlers::side_effects::tests::/) + test(/^storage_sweep::tests::/) + test(/^nip_fi_http::tests::/) + test(/^nip_fi_config::tests::/) + test(/^readiness::tests::/) + test(/^router::tests::/) + test(/^api::parse_query_tests::/) + test(/^api::git::transport::off_mode_precedence_tests::/) + test(=state::tests::neither_a_confirmed_inactive_community_nor_a_failed_lookup_admits_the_socket) + (kind(bin) & (test(/^tests::/) + test(/^composition_tests::/)) - test(/^tests::postgres_tests::/))' # ACP author-gate and queue tests protect the trust boundary between # relay events and agent prompts. They are infra-free; ignored lifecycle # tests remain excluded and run in their dedicated integration lanes. diff --git a/scripts/run-tests.sh b/scripts/run-tests.sh index 3732cdc476b..32bfa1c94bd 100755 --- a/scripts/run-tests.sh +++ b/scripts/run-tests.sh @@ -155,9 +155,9 @@ run_unit_tests() { run_test_step "buzz-acp unit tests" \ cargo test -p buzz-acp --lib -- --nocapture - # Mirror the three infra-free relay handler modules in `just test-unit`'s - # nextest expression. Keep the side-effects filter pinned to `::tests::` so - # it does not select the sibling Postgres-backed test module. + # Mirror the relay filters from `just test-unit`: the three handler modules, + # storage-snapshot helpers, readiness and router unit suites, and the single + # scoped admission regression in state::tests. run_test_step "buzz-relay channel authorization tests" \ cargo test -p buzz-relay --lib handlers::channel_authz:: -- --nocapture @@ -169,6 +169,15 @@ run_unit_tests() { run_test_step "buzz-relay storage snapshot tests" \ cargo test -p buzz-relay --lib storage_sweep::tests:: -- --nocapture + + run_test_step "buzz-relay readiness tests" \ + cargo test -p buzz-relay --lib readiness::tests:: -- --nocapture + + run_test_step "buzz-relay router tests" \ + cargo test -p buzz-relay --lib router::tests:: -- --nocapture + + run_test_step "buzz-relay admission regression test" \ + cargo test -p buzz-relay --lib state::tests::neither_a_confirmed_inactive_community_nor_a_failed_lookup_admits_the_socket -- --nocapture } # ---- DB / integration tests (infra required) -------------------------------- From 4b00d0cc58f22f3532773eb2e47c4c330e9d1855 Mon Sep 17 00:00:00 2001 From: tornquist Date: Thu, 24 Sep 2026 23:04:45 +0000 Subject: [PATCH 13/17] relay readiness: keep completion epoch as gauge with republisher Signed-off-by: tornquist Co-authored-by: Codex Signed-off-by: tornquist --- crates/buzz-relay/src/main.rs | 22 ++ crates/buzz-relay/src/metrics.rs | 4 +- crates/buzz-relay/src/readiness.rs | 332 ++++++++++++++++++++++++----- crates/buzz-relay/src/router.rs | 7 +- crates/buzz-relay/src/state.rs | 3 + deploy/charts/buzz/README.md | 17 +- 6 files changed, 317 insertions(+), 68 deletions(-) diff --git a/crates/buzz-relay/src/main.rs b/crates/buzz-relay/src/main.rs index 0cc665dc2b8..bc710f7c860 100644 --- a/crates/buzz-relay/src/main.rs +++ b/crates/buzz-relay/src/main.rs @@ -227,6 +227,10 @@ async fn run_relay_main(boot: BootTracker) -> anyhow::Result<()> { let usage_interval_secs = usage_metrics_interval_secs(); let usage_idle_timeout_secs = usage_metrics_idle_timeout_secs(usage_interval_secs); + let dependency_sample_completion_republish_interval = + buzz_relay::readiness::dependency_sample_completion_republish_interval( + usage_idle_timeout_secs, + ); let (boot, ()) = boot.run_required( StartupPhase::MetricsBind, || relay_metrics::try_install(config.metrics_port, usage_idle_timeout_secs), @@ -244,6 +248,7 @@ async fn run_relay_main(boot: BootTracker) -> anyhow::Result<()> { info!( port = config.metrics_port, idle_timeout_secs = usage_idle_timeout_secs, + completion_republish_secs = dependency_sample_completion_republish_interval.as_secs(), "Prometheus metrics exporter started" ); @@ -1119,6 +1124,22 @@ async fn run_relay_main(boot: BootTracker) -> anyhow::Result<()> { )); } + // Completion-epoch publisher: independent from sampling so the completion + // gauge survives recorder idle-eviction even when sampling stalls. + { + let publisher_state = Arc::clone(&state); + let cancel = publisher_state + .dependency_completion_publisher_cancel + .clone(); + tokio::spawn( + buzz_relay::readiness::run_dependency_sample_completion_publisher( + publisher_state, + dependency_sample_completion_republish_interval, + cancel, + ), + ); + } + // Cross-pod connection-control consumer: receive disconnect commands from // Redis pub/sub (published by the pod that recorded a ban) and close any // matching local sockets. A member's live connections may land on any pod, @@ -1293,6 +1314,7 @@ async fn run_relay_main(boot: BootTracker) -> anyhow::Result<()> { serve(router, health_router, Arc::clone(&state)).await?; state.community_revalidator_cancel.cancel(); state.dependency_sampler_cancel.cancel(); + state.dependency_completion_publisher_cancel.cancel(); // Signal the audit worker to stop accepting, flush buffered entries, and // exit. Uses a CancellationToken so it works regardless of how many diff --git a/crates/buzz-relay/src/metrics.rs b/crates/buzz-relay/src/metrics.rs index 7d8b42ea853..59bd90a0d7f 100644 --- a/crates/buzz-relay/src/metrics.rs +++ b/crates/buzz-relay/src/metrics.rs @@ -332,9 +332,9 @@ pub(crate) fn describe_readiness_metrics() { "buzz_readiness_state", "Latest private readiness-probe observation, where 1 is ready and 0 is shutting down" ); - metrics::describe_counter!( + metrics::describe_gauge!( "buzz_readiness_dependency_sample_completed_timestamp_seconds", - "Unix time the cached /_status dependency report completed, absent until the first sample completes" + "Unix time the cached /_status dependency report completed, absent until the first sample completes; sampler completion advances it and the publisher re-emits it" ); } diff --git a/crates/buzz-relay/src/readiness.rs b/crates/buzz-relay/src/readiness.rs index d193c3351f1..1ff50e5a79d 100644 --- a/crates/buzz-relay/src/readiness.rs +++ b/crates/buzz-relay/src/readiness.rs @@ -16,6 +16,7 @@ //! evaluations could be in flight at once. use std::future::Future; +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; use std::sync::{Arc, Mutex, PoisonError}; use std::time::{Duration, SystemTime}; @@ -34,6 +35,13 @@ const DEPENDENCY_TIMEOUT: Duration = Duration::from_secs(2); /// something current. Documented in `deploy/charts/buzz/README.md`. pub const DEPENDENCY_SAMPLE_INTERVAL: Duration = Duration::from_secs(30); +/// The completion-epoch publisher always refreshes at least this frequently. +/// +/// Main computes a cadence from the configured gauge idle timeout and caps it +/// at this value so the completion timestamp series survives idle eviction +/// without adding high-frequency noise. +const DEPENDENCY_SAMPLE_COMPLETION_REPUBLISH_MAX_INTERVAL: Duration = DEPENDENCY_SAMPLE_INTERVAL; + /// Age past which a cached report is reported stale rather than current. /// /// Two cadences: one full cycle can be missed by an evaluation that consumed @@ -54,8 +62,7 @@ pub(crate) const READINESS_REASON_LABELS: [&str; 2] = ["ready", "shutting_down"] /// - 2 probe reasons /// - 11 valid dependency/outcome pairs (Postgres 5, Redis 3, catalog 3) /// - 4 histograms x (15 configured buckets + `+Inf` + count + sum) = 72 -/// - 1 overall readiness gauge -/// - 1 sample-completion timestamp counter +/// - 2 readiness gauges (overall lifecycle + completion epoch) #[cfg(test)] pub(crate) const READINESS_RAW_SERIES_PER_POD: usize = 2 + 11 + (4 * 18) + 1 + 1; @@ -432,6 +439,22 @@ pub(crate) enum DependencySnapshot { }, } +/// Republish cadence for the completion-epoch gauge. +/// +/// The configured gauge idle timeout comes from `main.rs`; this returns a +/// bounded cadence that is strictly below that timeout and never slower than +/// the dependency sampler itself. +pub fn dependency_sample_completion_republish_interval(gauge_idle_timeout_secs: u64) -> Duration { + let idle_timeout_secs = gauge_idle_timeout_secs.max(1); + let refresh_secs = idle_timeout_secs.saturating_div(3).max(1); + let strict_upper_bound_secs = idle_timeout_secs.saturating_sub(1).max(1); + Duration::from_secs( + refresh_secs + .min(strict_upper_bound_secs) + .min(DEPENDENCY_SAMPLE_COMPLETION_REPUBLISH_MAX_INTERVAL.as_secs()), + ) +} + /// The per-pod owner of shared-dependency evaluation. /// /// [`run_dependency_sampler`] is the only caller of [`Self::sample`], so at @@ -440,6 +463,8 @@ pub(crate) enum DependencySnapshot { pub(crate) struct DependencyDiagnostics { evaluator: Arc, latest: Mutex>, + sample_completion_epoch_seconds: AtomicU64, + sample_completion_written: AtomicBool, } impl Default for DependencyDiagnostics { @@ -453,6 +478,8 @@ impl DependencyDiagnostics { Self { evaluator, latest: Mutex::new(None), + sample_completion_epoch_seconds: AtomicU64::new(0), + sample_completion_written: AtomicBool::new(false), } } @@ -470,7 +497,7 @@ impl DependencyDiagnostics { observed_at: Instant::now(), }; *self.latest.lock().unwrap_or_else(PoisonError::into_inner) = Some(sample); - record_dependency_sample_completion(SystemTime::now()); + self.record_dependency_sample_completion(SystemTime::now()); } /// The latest completed evaluation with its age. Starts no dependency work. @@ -488,6 +515,27 @@ impl DependencyDiagnostics { } } } + + fn record_dependency_sample_completion(&self, completed_at: SystemTime) { + let epoch_seconds = dependency_sample_completion_epoch_seconds(completed_at); + self.sample_completion_epoch_seconds + .store(epoch_seconds, Ordering::Release); + self.sample_completion_written + .store(true, Ordering::Release); + publish_dependency_sample_completion_metric(epoch_seconds); + } + + fn latest_sample_completion_epoch_seconds(&self) -> Option { + self.sample_completion_written + .load(Ordering::Acquire) + .then(|| self.sample_completion_epoch_seconds.load(Ordering::Acquire)) + } + + fn republish_dependency_sample_completion(&self) { + if let Some(epoch_seconds) = self.latest_sample_completion_epoch_seconds() { + publish_dependency_sample_completion_metric(epoch_seconds); + } + } } /// Runs the per-pod dependency sampling loop until `cancel` fires. @@ -499,7 +547,15 @@ impl DependencyDiagnostics { /// already slow. The first tick fires immediately, so the not-yet-sampled /// window is one evaluation long. pub async fn run_dependency_sampler(state: Arc, cancel: CancellationToken) { - let mut interval = tokio::time::interval(DEPENDENCY_SAMPLE_INTERVAL); + run_dependency_sampler_with_interval(state, cancel, DEPENDENCY_SAMPLE_INTERVAL).await; +} + +async fn run_dependency_sampler_with_interval( + state: Arc, + cancel: CancellationToken, + sample_interval: Duration, +) { + let mut interval = tokio::time::interval(sample_interval.max(Duration::from_millis(1))); interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Skip); loop { tokio::select! { @@ -515,6 +571,37 @@ pub async fn run_dependency_sampler(state: Arc, cancel: CancellationTo } } +/// Re-emits the latest completion epoch so the gauge survives recorder idle +/// eviction even when no newer dependency sample completes. +pub async fn run_dependency_sample_completion_publisher( + state: Arc, + republish_interval: Duration, + cancel: CancellationToken, +) { + run_dependency_sample_completion_publisher_for_diagnostics( + Arc::clone(&state.dependency_diagnostics), + republish_interval, + cancel, + ) + .await; +} + +async fn run_dependency_sample_completion_publisher_for_diagnostics( + diagnostics: Arc, + republish_interval: Duration, + cancel: CancellationToken, +) { + let mut interval = tokio::time::interval(republish_interval.max(Duration::from_millis(1))); + interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Skip); + loop { + tokio::select! { + biased; + _ = cancel.cancelled() => break, + _ = interval.tick() => diagnostics.republish_dependency_sample_completion(), + } + } +} + /// Records one dependency evaluation. Counters and durations only — dependency /// health has no publishable "current state" now that no probe consumes it; a /// per-dependency gauge would read as an authoritative verdict on infrastructure @@ -546,19 +633,22 @@ fn record_dependency_report(report: &DependencyReport) { /// — and grows on its own while this pod is wedged. A gauge carrying the age /// needs a writer to advance it, so the one failure it most needs to expose, a /// sampler that stopped running, is the one that would freeze it at its last -/// value and read as permanently fresh. Nothing but a completed sample writes -/// this, which also keeps the `buzz_storage_sweep_age_seconds` convention that -/// absence means "not yet sampled" rather than "fresh". +/// value and read as permanently fresh. A completed sample is the only thing +/// that may advance this epoch; the independent publisher only re-emits the +/// stored value so the series survives gauge idle-eviction. This keeps the +/// `buzz_storage_sweep_age_seconds` convention that absence means +/// "not yet sampled" rather than "fresh". /// -/// This is emitted as an absolute counter so the configured gauge-idle cleanup -/// cannot evict it between samples while scrapes continue. -fn record_dependency_sample_completion(completed_at: SystemTime) { - let epoch_seconds = completed_at +fn dependency_sample_completion_epoch_seconds(completed_at: SystemTime) -> u64 { + completed_at .duration_since(SystemTime::UNIX_EPOCH) .unwrap_or_default() - .as_secs(); - metrics::counter!("buzz_readiness_dependency_sample_completed_timestamp_seconds") - .absolute(epoch_seconds); + .as_secs() +} + +fn publish_dependency_sample_completion_metric(epoch_seconds: u64) { + metrics::gauge!("buzz_readiness_dependency_sample_completed_timestamp_seconds") + .set(epoch_seconds as f64); } fn record_dependency_attempt(dependency: &'static str, outcome: &'static str, duration: Duration) { @@ -712,6 +802,21 @@ mod tests { ); } + #[test] + fn completion_timestamp_republish_interval_stays_below_idle_timeout() { + assert_eq!( + dependency_sample_completion_republish_interval(900), + DEPENDENCY_SAMPLE_INTERVAL, + "default idle timeout should republish on the sampler cadence" + ); + assert_eq!( + dependency_sample_completion_republish_interval(15), + Duration::from_secs(5), + "the minimum configured idle timeout must still get multiple republishes" + ); + assert!(dependency_sample_completion_republish_interval(15) < Duration::from_secs(15)); + } + /// The readiness gauge and counter use the same immutable reason sampled by /// the private probe. A dependency evaluation — however bad — must never /// move them, which is what let a shared outage deroute every replica at @@ -865,22 +970,22 @@ mod tests { /// The completion timestamp written since the previous snapshot, if any. /// - /// `Snapshotter::snapshot` drains, so a window in which nothing wrote the - /// counter either omits the key entirely or, once registered, replays as + /// `Snapshotter::snapshot` drains, so a window in which nothing wrote this + /// metric either omits the key entirely or, once registered, replays as /// `0`. Zero is not a time any sample could have completed at, so folding /// it into `None` keeps "nobody wrote this in that window" expressible — /// the property a completion timestamp must have and an age cannot. - fn sample_completion_counter(snapshot: &Snapshot) -> Option { + fn sample_completion_metric_write(snapshot: &Snapshot) -> Option { exact_metric( snapshot, "buzz_readiness_dependency_sample_completed_timestamp_seconds", &[], ) .map(|value| { - let DebugValue::Counter(value) = value else { - panic!("the sample completion timestamp must be a counter"); + let DebugValue::Gauge(value) = value else { + panic!("the sample completion timestamp must be a gauge"); }; - *value + value.into_inner() as u64 }) .filter(|written| *written != 0) } @@ -900,6 +1005,38 @@ mod tests { }) } + fn sample_completion_metric_type_from_scrape(scrape: &str) -> Option<&str> { + scrape.lines().find_map(|line| { + line.strip_prefix( + "# TYPE buzz_readiness_dependency_sample_completed_timestamp_seconds ", + ) + }) + } + + /// Minimal model of Datadog OpenMetrics v2 with `send_monotonic_counter:true`. + /// + /// Gauge values are forwarded as-is. Counter values become per-scrape deltas + /// (`monotonic_count` / `.count`), so the exported sample itself is no + /// longer available to monitor queries. + fn datadog_openmetrics_v2_completion_epoch( + scrape: &str, + previous_counter_raw: &mut Option, + ) -> Option { + let raw = sample_completion_metric_value_from_scrape(scrape)?; + match sample_completion_metric_type_from_scrape(scrape) { + Some("gauge") => Some(raw), + Some("counter") => { + let transformed = previous_counter_raw + .map(|previous| raw.saturating_sub(previous)) + .unwrap_or(raw); + *previous_counter_raw = Some(raw); + Some(transformed) + } + Some(other) => panic!("unexpected metric type: {other}"), + None => panic!("missing sample completion metric type"), + } + } + /// The scrape-side half of the same question. Freshness is published as the /// Unix time the cached report completed, written only by a completed /// sample, so the age belongs to the query @@ -909,7 +1046,7 @@ mod tests { /// needs to expose — a sampler that stopped — is the one that would freeze /// it at its last value and read as permanently fresh. #[test] - fn the_completion_timestamp_counter_is_written_once_per_completed_sample() { + fn the_completion_timestamp_gauge_tracks_completed_samples() { let runtime = tokio::runtime::Builder::new_current_thread() .enable_all() .start_paused(true) @@ -924,7 +1061,7 @@ mod tests { let diagnostics = ready_diagnostics(); assert_eq!( - sample_completion_counter(&snapshotter.snapshot().into_vec()), + sample_completion_metric_write(&snapshotter.snapshot().into_vec()), None, "absence is the not-yet-sampled signal, not a fresh zero" ); @@ -932,7 +1069,7 @@ mod tests { let before_first = epoch_seconds_now(); diagnostics.sample(&db, &redis_pool).await; let after_first = epoch_seconds_now(); - let first = sample_completion_counter(&snapshotter.snapshot().into_vec()) + let first = sample_completion_metric_write(&snapshotter.snapshot().into_vec()) .expect("a completed sample must publish when it completed"); assert!( (before_first..=after_first).contains(&first), @@ -943,9 +1080,9 @@ mod tests { // Paused time: no task, timer, or aging loop can run here. tokio::time::advance(DEPENDENCY_SAMPLE_STALE_AFTER + Duration::from_secs(1)).await; assert_eq!( - sample_completion_counter(&snapshotter.snapshot().into_vec()), + sample_completion_metric_write(&snapshotter.snapshot().into_vec()), None, - "only a completed sample may write the counter, so the age a \ + "only a completed sample may write the gauge, so the age a \ query derives from it grows with no server-side writer" ); assert!( @@ -956,7 +1093,7 @@ mod tests { let before_second = epoch_seconds_now(); diagnostics.sample(&db, &redis_pool).await; let after_second = epoch_seconds_now(); - let second = sample_completion_counter(&snapshotter.snapshot().into_vec()) + let second = sample_completion_metric_write(&snapshotter.snapshot().into_vec()) .expect("the next completed sample republishes the timestamp"); assert!( (before_second..=after_second).contains(&second) && second >= first, @@ -971,55 +1108,140 @@ mod tests { } #[test] - fn scrape_retains_the_completion_timestamp_across_gauge_idle_timeout() { - let timeout = Duration::from_secs(1); - let (recorder, handle) = - crate::metrics::readiness_test_recorder_with_idle_timeout(timeout.as_secs()); + fn openmetrics_v2_preserves_epoch_only_when_raw_prometheus_type_is_gauge() { + let (recorder, handle) = crate::metrics::readiness_test_recorder(); + let mut previous_counter_raw = None; assert_eq!( - sample_completion_metric_value_from_scrape(&handle.render()), + datadog_openmetrics_v2_completion_epoch(&handle.render(), &mut previous_counter_raw), None, - "absence before the first completion is the not-yet-sampled signal" + "absence before the first completion remains absence after transform" ); let first = 4_750_000_001_u64; metrics::with_local_recorder(&recorder, || { - record_dependency_sample_completion( - SystemTime::UNIX_EPOCH + Duration::from_secs(4_750_000_001), - ); + publish_dependency_sample_completion_metric(first); }); + let after_first_completion = handle.render(); assert_eq!( - sample_completion_metric_value_from_scrape(&handle.render()), + datadog_openmetrics_v2_completion_epoch( + &after_first_completion, + &mut previous_counter_raw, + ), Some(first), - "a completed sample publishes its Unix completion time" + "after first completion the transformed value must be the completion epoch" ); - // Keep scraping while the configured idle timeout elapses; this metric must - // stay queryable so freshness checks keep working during a stalled - // sampler. - std::thread::sleep(timeout + Duration::from_millis(200)); - assert_eq!( - sample_completion_metric_value_from_scrape(&handle.render()), - Some(first), - "completion time must remain exported after idle timeout" - ); - std::thread::sleep(Duration::from_millis(100)); + // Same raw scrape value after idle timeout: sampler produced no new completion. assert_eq!( - sample_completion_metric_value_from_scrape(&handle.render()), + datadog_openmetrics_v2_completion_epoch( + &after_first_completion, + &mut previous_counter_raw, + ), Some(first), - "continued scrapes must not age this metric out" + "idle-timeout survival still must preserve the full epoch" ); + let second = 4_750_000_005_u64; metrics::with_local_recorder(&recorder, || { - record_dependency_sample_completion( - SystemTime::UNIX_EPOCH + Duration::from_secs(4_750_000_005), - ); + publish_dependency_sample_completion_metric(second); }); + let after_later_completion = handle.render(); assert_eq!( - sample_completion_metric_value_from_scrape(&handle.render()), - Some(4_750_000_005_u64), - "the next completed sample republished the newer completion epoch" + datadog_openmetrics_v2_completion_epoch( + &after_later_completion, + &mut previous_counter_raw, + ), + Some(second), + "a later completion must transform to the new full epoch" ); + + // Same raw value again while only the sampler is stopped. + assert_eq!( + datadog_openmetrics_v2_completion_epoch( + &after_later_completion, + &mut previous_counter_raw, + ), + Some(second), + "sampler stoppage must not collapse the epoch to a delta" + ); + } + + async fn wait_for_sample_completion_scrape_value( + handle: &metrics_exporter_prometheus::PrometheusHandle, + predicate: impl Fn(u64) -> bool, + ) -> u64 { + let deadline = std::time::Instant::now() + Duration::from_secs(5); + loop { + if let Some(value) = sample_completion_metric_value_from_scrape(&handle.render()) { + if predicate(value) { + return value; + } + } + assert!( + std::time::Instant::now() < deadline, + "timed out waiting for completion timestamp scrape value" + ); + tokio::time::sleep(Duration::from_millis(25)).await; + } + } + + #[test] + fn scrape_retains_the_completion_timestamp_across_gauge_idle_timeout() { + let timeout = Duration::from_secs(1); + let republish_interval = Duration::from_millis(100); + let runtime = tokio::runtime::Builder::new_current_thread() + .enable_all() + .build() + .expect("current-thread runtime"); + let (recorder, handle) = + crate::metrics::readiness_test_recorder_with_idle_timeout(timeout.as_secs()); + + metrics::with_local_recorder(&recorder, || { + runtime.block_on(async { + let (db, redis_pool) = unreachable_dependencies(); + let diagnostics = Arc::new(ready_diagnostics()); + let publisher_cancel = CancellationToken::new(); + let publisher = tokio::spawn( + run_dependency_sample_completion_publisher_for_diagnostics( + diagnostics.clone(), + republish_interval, + publisher_cancel.clone(), + )); + + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + None, + "absence before the first completion is the not-yet-sampled signal" + ); + + diagnostics.sample(&db, &redis_pool).await; + let first = wait_for_sample_completion_scrape_value(&handle, |value| value > 0).await; + + tokio::time::sleep(timeout + Duration::from_millis(200)).await; + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + Some(first), + "publisher must keep the first completion epoch exported after idle timeout" + ); + + while epoch_seconds_now() <= first { + tokio::time::sleep(Duration::from_millis(25)).await; + } + diagnostics.sample(&db, &redis_pool).await; + let second = wait_for_sample_completion_scrape_value(&handle, |value| value > first).await; + + tokio::time::sleep(timeout + Duration::from_millis(200)).await; + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + Some(second), + "with no further samples, publisher must keep the latest epoch while the sampler is stopped" + ); + + publisher_cancel.cancel(); + publisher.await.expect("completion publisher task"); + }); + }); } #[test] diff --git a/crates/buzz-relay/src/router.rs b/crates/buzz-relay/src/router.rs index d97dbdeecad..3e96c02c13d 100644 --- a/crates/buzz-relay/src/router.rs +++ b/crates/buzz-relay/src/router.rs @@ -1530,11 +1530,12 @@ mod tests { ); assert!(!final_scrape.contains("sensitive-sql-or-url")); // Freshness is part of the frozen contract: one unlabelled - // counter carrying when the cached report completed, so - // `time() - ` ages a stalled sampler out from a scrape + // gauge carrying when the cached report completed. The sampler + // advances it and the publisher re-emits it, so + // `time() - ` ages a stalled sampler out from a scrape // alone. assert!(final_scrape.contains( - "# TYPE buzz_readiness_dependency_sample_completed_timestamp_seconds counter" + "# TYPE buzz_readiness_dependency_sample_completed_timestamp_seconds gauge" )); assert_eq!( final_scrape diff --git a/crates/buzz-relay/src/state.rs b/crates/buzz-relay/src/state.rs index a297b6a9d4e..0bcab5d63a4 100644 --- a/crates/buzz-relay/src/state.rs +++ b/crates/buzz-relay/src/state.rs @@ -834,6 +834,8 @@ pub struct AppState { pub(crate) dependency_diagnostics: Arc, /// Stops only the periodic dependency sampler during graceful shutdown. pub dependency_sampler_cancel: CancellationToken, + /// Stops only the completion-epoch publisher during graceful shutdown. + pub dependency_completion_publisher_cancel: CancellationToken, /// Process start time — used by `/_status` endpoint. pub started_at: Instant, /// Shared, community-scoped NIP-98 replay prevention. @@ -1061,6 +1063,7 @@ impl AppState { shutting_down: Arc::new(AtomicBool::new(false)), dependency_diagnostics: Arc::new(crate::readiness::DependencyDiagnostics::default()), dependency_sampler_cancel: CancellationToken::new(), + dependency_completion_publisher_cancel: CancellationToken::new(), started_at: Instant::now(), nip98_replay, gif_http_client, diff --git a/deploy/charts/buzz/README.md b/deploy/charts/buzz/README.md index 245eac25e34..2ce1dc11078 100644 --- a/deploy/charts/buzz/README.md +++ b/deploy/charts/buzz/README.md @@ -174,7 +174,7 @@ listener returns the same lifecycle answer but does not change these metrics. | `buzz_readiness_state` | gauge | `check="overall"`; latest private probe observation, 1 ready or 0 shutting down | `/_readiness` | | `buzz_readiness_dependency_checks_total` | counter | `dependency`, typed bounded `outcome` | dependency sampler | | `buzz_readiness_check_duration_seconds` | histogram | `check` only | dependency sampler | -| `buzz_readiness_dependency_sample_completed_timestamp_seconds` | counter | none; Unix time the cached report completed | dependency sampler | +| `buzz_readiness_dependency_sample_completed_timestamp_seconds` | gauge | none; Unix time the cached report completed | completion publisher | The three dependency families keep their `buzz_readiness_*` names for dashboard continuity, but nothing about them is request-driven any more: the 30-second @@ -183,18 +183,19 @@ endpoint no longer produces a flat dashboard during the outage it exists to explain. `buzz_readiness_dependency_sample_completed_timestamp_seconds` carries **when -the cached report completed**, in Unix seconds. The relay writes it once per -completed sample, immediately after the cache is replaced, and nothing else -writes it — there is no background loop that ages it. So the value stands still -when sampling stops, and the time elapsed since it was written is whatever the -reader computes at read time. +the cached report completed**, in Unix seconds. The relay sampler is the only +owner allowed to advance that epoch, and it writes it immediately after the +cache is replaced. A separate bounded publisher re-emits the stored epoch often +enough to survive local gauge idle-timeout; republishing never advances the +timestamp. So the value stands still when sampling stops, and the time elapsed +since it was written is whatever the reader computes at read time. Following the `buzz_storage_sweep_age_seconds` convention, the series is not emitted until the first sample completes: its absence means "not yet sampled", not "fresh". That is the whole server-side contract. Freshness alerting is built from this -counter in the monitoring provider, and the monitor query, thresholds, and +gauge in the monitoring provider, and the monitor query, thresholds, and per-pod tag grouping belong with the deployment's monitor configuration rather than in this chart — they depend on the provider's query grammar and on the tags its agent attaches, neither of which this repo owns. @@ -208,7 +209,7 @@ reading a single pod is already on the `sample`, `sample_age_seconds`, and `sample_interval_seconds` fields of `/_status` above. The schema has a ceiling of 87 raw Prometheus series per pod: 2 probe reasons, -11 valid dependency/outcome pairs, 72 histogram series, and 1 gauge plus 1 completion-timestamp counter. Do not +11 valid dependency/outcome pairs, 72 histogram series, and 2 gauges (overall lifecycle + completion timestamp). Do not add pod, ReplicaSet, version, rollout, error text, SQL, URL, tenant, user, community, pubkey, header, query, or other request-controlled labels. A readiness probe records no dependency attempt or latency sample at all. From 74f210b739a1a3b2a884c2ca20f1e4d81453fb09 Mon Sep 17 00:00:00 2001 From: tornquist Date: Fri, 25 Sep 2026 01:07:02 +0000 Subject: [PATCH 14/17] fix(relay): stop a racing republish from regressing the completion epoch MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The completion-epoch gauge has two writers: the dependency sampler, which owns the epoch, and the idle-refresh publisher, which may only re-emit it. The publisher read the stored epoch and wrote it as two separate steps, so a sample completing in between left the older epoch as the last write — the exported series moved backwards for up to one publisher interval, which is exactly the window freshness alerting reads. The metrics facade offers a bare `set` with no compare-and-set, so the ordering has to come from the writers. Serializing them under one lock would put the sampler's authoritative write behind an idle refresh; instead the republisher now verifies after its write that the epoch it wrote is still the stored one, and re-emits the newer one if a completion landed while that write was in flight. Another pass costs another completed sample, so it ends as soon as nothing is racing it. The regression parks a republish inside the recorder — the last point of its write, after it has read the epoch — completes a newer sample behind it, then releases it and asserts the scrape still reports the newer completion. Against the unfixed publisher it reports the older epoch. Co-Authored-By: Claude Opus 5 Signed-off-by: tornquist --- crates/buzz-relay/src/readiness.rs | 239 ++++++++++++++++++++++++++++- deploy/charts/buzz/README.md | 7 +- 2 files changed, 243 insertions(+), 3 deletions(-) diff --git a/crates/buzz-relay/src/readiness.rs b/crates/buzz-relay/src/readiness.rs index 1ff50e5a79d..b6a1b78b9c2 100644 --- a/crates/buzz-relay/src/readiness.rs +++ b/crates/buzz-relay/src/readiness.rs @@ -531,9 +531,23 @@ impl DependencyDiagnostics { .then(|| self.sample_completion_epoch_seconds.load(Ordering::Acquire)) } + /// Re-emits the stored epoch, then checks it is still the stored one. + /// + /// A sample can complete and publish a newer epoch while this write is in + /// flight, and the metrics facade exposes only a bare `set`, so nothing + /// downstream rejects the older value once it lands last. Verifying after + /// the write — rather than before it — is what closes that window: a + /// republish that lost the race re-emits the newer epoch instead of + /// leaving the exported series moved backwards. Another pass costs another + /// completed sample, so this ends as soon as no completion is racing it. fn republish_dependency_sample_completion(&self) { - if let Some(epoch_seconds) = self.latest_sample_completion_epoch_seconds() { + let mut published = None; + while let Some(epoch_seconds) = self.latest_sample_completion_epoch_seconds() { + if published == Some(epoch_seconds) { + break; + } publish_dependency_sample_completion_metric(epoch_seconds); + published = Some(epoch_seconds); } } } @@ -1244,6 +1258,229 @@ mod tests { }); } + /// How long a park step waits before it is a failure rather than a hang. + const PARK_SIGNAL_TIMEOUT: Duration = Duration::from_secs(10); + + /// A completion-epoch gauge write that can be stopped at the recorder + /// boundary — the last instruction of a publish, after the writer has + /// already read the epoch it is publishing. + /// + /// Arming names one epoch value and fires once, so the sampler's own write + /// passes straight through and only the republish under test parks. + struct PublishPark { + armed_for: Mutex>, + parked_tx: std::sync::mpsc::SyncSender<()>, + parked_rx: Mutex>, + release_tx: std::sync::mpsc::SyncSender<()>, + release_rx: Mutex>, + } + + impl PublishPark { + fn new() -> Self { + let (parked_tx, parked_rx) = std::sync::mpsc::sync_channel(1); + let (release_tx, release_rx) = std::sync::mpsc::sync_channel(1); + Self { + armed_for: Mutex::new(None), + parked_tx, + parked_rx: Mutex::new(parked_rx), + release_tx, + release_rx: Mutex::new(release_rx), + } + } + + fn arm(&self, epoch_seconds: u64) { + *self.armed_for.lock().expect("park state") = Some(epoch_seconds); + } + + fn park_if_armed(&self, epoch_seconds: u64) { + { + let mut armed = self.armed_for.lock().expect("park state"); + if *armed != Some(epoch_seconds) { + return; + } + *armed = None; + } + self.parked_tx.send(()).expect("announce the parked write"); + self.release_rx + .lock() + .expect("release channel") + .recv_timeout(PARK_SIGNAL_TIMEOUT) + .expect("the parked write must be released"); + } + + fn wait_until_parked(&self) { + self.parked_rx + .lock() + .expect("park channel") + .recv_timeout(PARK_SIGNAL_TIMEOUT) + .expect("the armed write must reach the recorder"); + } + + fn release(&self) { + self.release_tx.send(()).expect("release the parked write"); + } + } + + /// Delegates to the real Prometheus recorder, with the completion-epoch + /// gauge routed through [`PublishPark`]. + struct ParkingRecorder { + inner: metrics_exporter_prometheus::PrometheusRecorder, + park: Arc, + } + + struct ParkingGauge { + inner: metrics::Gauge, + park: Arc, + } + + impl metrics::GaugeFn for ParkingGauge { + fn increment(&self, value: f64) { + self.inner.increment(value); + } + + fn decrement(&self, value: f64) { + self.inner.decrement(value); + } + + fn set(&self, value: f64) { + self.park.park_if_armed(value as u64); + self.inner.set(value); + } + } + + impl metrics::Recorder for ParkingRecorder { + fn describe_counter( + &self, + key: metrics::KeyName, + unit: Option, + description: metrics::SharedString, + ) { + self.inner.describe_counter(key, unit, description); + } + + fn describe_gauge( + &self, + key: metrics::KeyName, + unit: Option, + description: metrics::SharedString, + ) { + self.inner.describe_gauge(key, unit, description); + } + + fn describe_histogram( + &self, + key: metrics::KeyName, + unit: Option, + description: metrics::SharedString, + ) { + self.inner.describe_histogram(key, unit, description); + } + + fn register_counter( + &self, + key: &metrics::Key, + metadata: &metrics::Metadata<'_>, + ) -> metrics::Counter { + self.inner.register_counter(key, metadata) + } + + fn register_gauge( + &self, + key: &metrics::Key, + metadata: &metrics::Metadata<'_>, + ) -> metrics::Gauge { + let gauge = self.inner.register_gauge(key, metadata); + if key.name() == "buzz_readiness_dependency_sample_completed_timestamp_seconds" { + metrics::Gauge::from_arc(Arc::new(ParkingGauge { + inner: gauge, + park: Arc::clone(&self.park), + })) + } else { + gauge + } + } + + fn register_histogram( + &self, + key: &metrics::Key, + metadata: &metrics::Metadata<'_>, + ) -> metrics::Histogram { + self.inner.register_histogram(key, metadata) + } + } + + /// Two tasks write this gauge — the sampler, which owns the epoch, and the + /// idle-refresh publisher, which may only re-emit it — and the metrics + /// facade offers a bare `set` with no compare-and-set to lean on. So a + /// republish that read the stored epoch before a sample completed can still + /// be inside its own write when the newer epoch lands, and plain last-write + /// -wins would leave the exported series moved backwards until the next + /// republish tick. + /// + /// This parks the republish at the recorder, the last point in its write, + /// completes a newer sample behind it — which must not be blocked by the + /// parked republish — and only then releases it. The scrape must report the + /// newer completion. Times are injected so the two epochs are exact and the + /// interleaving does not depend on the wall clock. + #[test] + fn a_republish_racing_a_completion_cannot_move_the_exported_epoch_backwards() { + const EARLIER_EPOCH_SECONDS: u64 = 1_700_000_000; + const LATER_EPOCH_SECONDS: u64 = 1_700_000_030; + + let (prometheus, handle) = crate::metrics::readiness_test_recorder(); + let park = Arc::new(PublishPark::new()); + let recorder = Arc::new(ParkingRecorder { + inner: prometheus, + park: Arc::clone(&park), + }); + let diagnostics = Arc::new(ready_diagnostics()); + + metrics::with_local_recorder(recorder.as_ref(), || { + diagnostics.record_dependency_sample_completion( + SystemTime::UNIX_EPOCH + Duration::from_secs(EARLIER_EPOCH_SECONDS), + ); + }); + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + Some(EARLIER_EPOCH_SECONDS), + "the first completion owns the epoch" + ); + + park.arm(EARLIER_EPOCH_SECONDS); + let republisher = std::thread::spawn({ + let recorder = Arc::clone(&recorder); + let diagnostics = Arc::clone(&diagnostics); + move || { + metrics::with_local_recorder(recorder.as_ref(), || { + diagnostics.republish_dependency_sample_completion(); + }); + } + }); + + park.wait_until_parked(); + + metrics::with_local_recorder(recorder.as_ref(), || { + diagnostics.record_dependency_sample_completion( + SystemTime::UNIX_EPOCH + Duration::from_secs(LATER_EPOCH_SECONDS), + ); + }); + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + Some(LATER_EPOCH_SECONDS), + "a completed sample must publish its epoch while a republish is still in flight" + ); + + park.release(); + republisher.join().expect("republish thread"); + + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + Some(LATER_EPOCH_SECONDS), + "a republish that lost the race must not re-export the epoch it read \ + before the newer sample completed" + ); + } + #[test] fn readiness_reason_labels_are_the_closed_lifecycle_set() { assert_eq!( diff --git a/deploy/charts/buzz/README.md b/deploy/charts/buzz/README.md index 2ce1dc11078..c1372e1dd72 100644 --- a/deploy/charts/buzz/README.md +++ b/deploy/charts/buzz/README.md @@ -187,8 +187,11 @@ the cached report completed**, in Unix seconds. The relay sampler is the only owner allowed to advance that epoch, and it writes it immediately after the cache is replaced. A separate bounded publisher re-emits the stored epoch often enough to survive local gauge idle-timeout; republishing never advances the -timestamp. So the value stands still when sampling stops, and the time elapsed -since it was written is whatever the reader computes at read time. +timestamp. Nor does it ever move the series backwards: a republish that raced a +completing sample re-emits the newer epoch it finds, so the exported value never +regresses to a completion the pod has already passed. So the value stands still +when sampling stops, and the time elapsed since it was written is whatever the +reader computes at read time. Following the `buzz_storage_sweep_age_seconds` convention, the series is not emitted until the first sample completes: its absence means "not yet sampled", From a566a293af0b0badea19ba1072ade5ed1db8f622 Mon Sep 17 00:00:00 2001 From: tornquist Date: Fri, 25 Sep 2026 15:22:17 +0000 Subject: [PATCH 15/17] fix(relay): unify readiness sampler+publisher startup seam Signed-off-by: tornquist Co-authored-by: Amp Signed-off-by: tornquist --- crates/buzz-relay/src/main.rs | 31 ++------- crates/buzz-relay/src/readiness.rs | 103 +++++++++++++++++++---------- deploy/charts/buzz/README.md | 6 +- 3 files changed, 78 insertions(+), 62 deletions(-) diff --git a/crates/buzz-relay/src/main.rs b/crates/buzz-relay/src/main.rs index bc710f7c860..d2cf5fa7871 100644 --- a/crates/buzz-relay/src/main.rs +++ b/crates/buzz-relay/src/main.rs @@ -1111,32 +1111,13 @@ async fn run_relay_main(boot: BootTracker) -> anyhow::Result<()> { )); } - // Per-pod dependency sampler: the single owner of Postgres/Redis/deletion- - // catalog evaluation. It publishes the dependency metrics and caches the - // report `/_status` serves, so neither operator polling nor a quiet endpoint - // changes how often a shared dependency is probed. + // Per-pod dependency diagnostics runtime: one seam starts the dependency + // sampler and its independent completion-epoch republisher together. { - let sampler_state = Arc::clone(&state); - let cancel = sampler_state.dependency_sampler_cancel.clone(); - tokio::spawn(buzz_relay::readiness::run_dependency_sampler( - sampler_state, - cancel, - )); - } - - // Completion-epoch publisher: independent from sampling so the completion - // gauge survives recorder idle-eviction even when sampling stalls. - { - let publisher_state = Arc::clone(&state); - let cancel = publisher_state - .dependency_completion_publisher_cancel - .clone(); - tokio::spawn( - buzz_relay::readiness::run_dependency_sample_completion_publisher( - publisher_state, - dependency_sample_completion_republish_interval, - cancel, - ), + let diagnostics_state = Arc::clone(&state); + buzz_relay::readiness::start_dependency_sampler_and_completion_publisher( + diagnostics_state, + dependency_sample_completion_republish_interval, ); } diff --git a/crates/buzz-relay/src/readiness.rs b/crates/buzz-relay/src/readiness.rs index b6a1b78b9c2..9e490939793 100644 --- a/crates/buzz-relay/src/readiness.rs +++ b/crates/buzz-relay/src/readiness.rs @@ -561,13 +561,49 @@ impl DependencyDiagnostics { /// already slow. The first tick fires immediately, so the not-yet-sampled /// window is one evaluation long. pub async fn run_dependency_sampler(state: Arc, cancel: CancellationToken) { - run_dependency_sampler_with_interval(state, cancel, DEPENDENCY_SAMPLE_INTERVAL).await; + run_dependency_sampler_for_diagnostics( + Arc::clone(&state.dependency_diagnostics), + state.db.clone(), + state.redis_pool.clone(), + DEPENDENCY_SAMPLE_INTERVAL, + cancel, + ) + .await; } -async fn run_dependency_sampler_with_interval( +/// Starts the dependency sampler and completion republisher together. +/// +/// Main calls this once at startup so sampler and publisher ownership lives at +/// one seam instead of being wired independently. +pub fn start_dependency_sampler_and_completion_publisher( state: Arc, - cancel: CancellationToken, + republish_interval: Duration, +) { + let sampler_state = Arc::clone(&state); + tokio::spawn(run_dependency_sampler_for_diagnostics( + Arc::clone(&sampler_state.dependency_diagnostics), + sampler_state.db.clone(), + sampler_state.redis_pool.clone(), + DEPENDENCY_SAMPLE_INTERVAL, + sampler_state.dependency_sampler_cancel.clone(), + )); + + let publisher_state = Arc::clone(&state); + tokio::spawn(run_dependency_sample_completion_publisher_for_diagnostics( + Arc::clone(&publisher_state.dependency_diagnostics), + republish_interval, + publisher_state + .dependency_completion_publisher_cancel + .clone(), + )); +} + +async fn run_dependency_sampler_for_diagnostics( + diagnostics: Arc, + db: Db, + redis_pool: deadpool_redis::Pool, sample_interval: Duration, + cancel: CancellationToken, ) { let mut interval = tokio::time::interval(sample_interval.max(Duration::from_millis(1))); interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Skip); @@ -576,10 +612,7 @@ async fn run_dependency_sampler_with_interval( biased; _ = cancel.cancelled() => break, _ = interval.tick() => { - state - .dependency_diagnostics - .sample(&state.db, &state.redis_pool) - .await; + diagnostics.sample(&db, &redis_pool).await; } } } @@ -1201,7 +1234,7 @@ mod tests { } #[test] - fn scrape_retains_the_completion_timestamp_across_gauge_idle_timeout() { + fn dependency_runtime_retains_the_completion_timestamp_when_only_sampler_stops() { let timeout = Duration::from_secs(1); let republish_interval = Duration::from_millis(100); let runtime = tokio::runtime::Builder::new_current_thread() @@ -1213,47 +1246,49 @@ mod tests { metrics::with_local_recorder(&recorder, || { runtime.block_on(async { - let (db, redis_pool) = unreachable_dependencies(); - let diagnostics = Arc::new(ready_diagnostics()); - let publisher_cancel = CancellationToken::new(); - let publisher = tokio::spawn( - run_dependency_sample_completion_publisher_for_diagnostics( - diagnostics.clone(), + let mut state = crate::state::tests::test_state_with_database_url( + "postgres://127.0.0.1:1/buzz", + ) + .await; + Arc::get_mut(&mut state) + .expect("sole readiness state") + .set_dependency_evaluator(Arc::new(FixedEvaluator( + DependencyReport::from_results( + TimedOutcome::new(PostgresOutcome::Success, Duration::from_millis(3)), + TimedOutcome::new(RedisOutcome::Success, Duration::from_millis(2)), + TimedOutcome::new( + DeletionCatalogOutcome::Success, + Duration::from_millis(1), + ), + Duration::from_millis(3), + ), + ))); + + start_dependency_sampler_and_completion_publisher( + Arc::clone(&state), republish_interval, - publisher_cancel.clone(), - )); - - assert_eq!( - sample_completion_metric_value_from_scrape(&handle.render()), - None, - "absence before the first completion is the not-yet-sampled signal" ); - diagnostics.sample(&db, &redis_pool).await; - let first = wait_for_sample_completion_scrape_value(&handle, |value| value > 0).await; + let first = + wait_for_sample_completion_scrape_value(&handle, |value| value > 0).await; + + state.dependency_sampler_cancel.cancel(); tokio::time::sleep(timeout + Duration::from_millis(200)).await; assert_eq!( sample_completion_metric_value_from_scrape(&handle.render()), Some(first), - "publisher must keep the first completion epoch exported after idle timeout" + "publisher must keep the completion epoch exported after idle timeout" ); - while epoch_seconds_now() <= first { - tokio::time::sleep(Duration::from_millis(25)).await; - } - diagnostics.sample(&db, &redis_pool).await; - let second = wait_for_sample_completion_scrape_value(&handle, |value| value > first).await; - tokio::time::sleep(timeout + Duration::from_millis(200)).await; assert_eq!( sample_completion_metric_value_from_scrape(&handle.render()), - Some(second), - "with no further samples, publisher must keep the latest epoch while the sampler is stopped" + Some(first), + "with no sampler activity, publisher must keep exporting the stored epoch" ); - publisher_cancel.cancel(); - publisher.await.expect("completion publisher task"); + state.dependency_completion_publisher_cancel.cancel(); }); }); } diff --git a/deploy/charts/buzz/README.md b/deploy/charts/buzz/README.md index c1372e1dd72..f5075fd19d5 100644 --- a/deploy/charts/buzz/README.md +++ b/deploy/charts/buzz/README.md @@ -187,9 +187,9 @@ the cached report completed**, in Unix seconds. The relay sampler is the only owner allowed to advance that epoch, and it writes it immediately after the cache is replaced. A separate bounded publisher re-emits the stored epoch often enough to survive local gauge idle-timeout; republishing never advances the -timestamp. Nor does it ever move the series backwards: a republish that raced a -completing sample re-emits the newer epoch it finds, so the exported value never -regresses to a completion the pod has already passed. So the value stands still +timestamp. If a republish races a newer completion, one scrape can briefly see +the older epoch, but the republish path verifies after writing and repairs to the +newer stored epoch before that republish call returns. So the value stands still when sampling stops, and the time elapsed since it was written is whatever the reader computes at read time. From c58cee54f4ca8b0fdcd0ab7443767eacdc55e54e Mon Sep 17 00:00:00 2001 From: tornquist Date: Fri, 25 Sep 2026 17:53:52 +0000 Subject: [PATCH 16/17] fix(relay): reuse readiness runtime runners Signed-off-by: tornquist Co-authored-by: Codex Signed-off-by: tornquist --- crates/buzz-relay/src/readiness.rs | 94 ++++++++++++++++++------------ 1 file changed, 58 insertions(+), 36 deletions(-) diff --git a/crates/buzz-relay/src/readiness.rs b/crates/buzz-relay/src/readiness.rs index 9e490939793..624a3649adc 100644 --- a/crates/buzz-relay/src/readiness.rs +++ b/crates/buzz-relay/src/readiness.rs @@ -457,9 +457,11 @@ pub fn dependency_sample_completion_republish_interval(gauge_idle_timeout_secs: /// The per-pod owner of shared-dependency evaluation. /// -/// [`run_dependency_sampler`] is the only caller of [`Self::sample`], so at -/// most one evaluation exists at a time and no request path can start another. -/// `/_status` reads [`Self::snapshot`], which touches no dependency. +/// The production [`run_dependency_sampler`] loop is the sole runtime owner of +/// [`Self::sample`], so at most one evaluation exists at a time and no request +/// path can start another. The companion completion publisher only reads the +/// stored epoch, while `/_status` reads [`Self::snapshot`]; neither touches a +/// dependency. pub(crate) struct DependencyDiagnostics { evaluator: Arc, latest: Mutex>, @@ -579,22 +581,14 @@ pub fn start_dependency_sampler_and_completion_publisher( state: Arc, republish_interval: Duration, ) { - let sampler_state = Arc::clone(&state); - tokio::spawn(run_dependency_sampler_for_diagnostics( - Arc::clone(&sampler_state.dependency_diagnostics), - sampler_state.db.clone(), - sampler_state.redis_pool.clone(), - DEPENDENCY_SAMPLE_INTERVAL, - sampler_state.dependency_sampler_cancel.clone(), - )); + let sampler_cancel = state.dependency_sampler_cancel.clone(); + tokio::spawn(run_dependency_sampler(Arc::clone(&state), sampler_cancel)); - let publisher_state = Arc::clone(&state); - tokio::spawn(run_dependency_sample_completion_publisher_for_diagnostics( - Arc::clone(&publisher_state.dependency_diagnostics), + let publisher_cancel = state.dependency_completion_publisher_cancel.clone(); + tokio::spawn(run_dependency_sample_completion_publisher( + state, republish_interval, - publisher_state - .dependency_completion_publisher_cancel - .clone(), + publisher_cancel, )); } @@ -967,15 +961,32 @@ mod tests { } } + struct DelayedEvaluator { + report: DependencyReport, + started: Arc, + release: Arc, + } + + #[async_trait::async_trait] + impl DependencyEvaluator for DelayedEvaluator { + async fn evaluate(&self, _db: &Db, _redis_pool: &deadpool_redis::Pool) -> DependencyReport { + self.started.notify_one(); + self.release.notified().await; + self.report + } + } + + fn ready_report() -> DependencyReport { + DependencyReport::from_results( + TimedOutcome::new(PostgresOutcome::Success, Duration::from_millis(3)), + TimedOutcome::new(RedisOutcome::Success, Duration::from_millis(2)), + TimedOutcome::new(DeletionCatalogOutcome::Success, Duration::from_millis(1)), + Duration::from_millis(3), + ) + } + fn ready_diagnostics() -> DependencyDiagnostics { - DependencyDiagnostics::with_evaluator(Arc::new(FixedEvaluator( - DependencyReport::from_results( - TimedOutcome::new(PostgresOutcome::Success, Duration::from_millis(3)), - TimedOutcome::new(RedisOutcome::Success, Duration::from_millis(2)), - TimedOutcome::new(DeletionCatalogOutcome::Success, Duration::from_millis(1)), - Duration::from_millis(3), - ), - ))) + DependencyDiagnostics::with_evaluator(Arc::new(FixedEvaluator(ready_report()))) } fn sampled(snapshot: DependencySnapshot) -> (Duration, bool) { @@ -1239,6 +1250,7 @@ mod tests { let republish_interval = Duration::from_millis(100); let runtime = tokio::runtime::Builder::new_current_thread() .enable_all() + .start_paused(true) .build() .expect("current-thread runtime"); let (recorder, handle) = @@ -1250,29 +1262,39 @@ mod tests { "postgres://127.0.0.1:1/buzz", ) .await; + let sample_started = Arc::new(tokio::sync::Notify::new()); + let release_sample = Arc::new(tokio::sync::Notify::new()); Arc::get_mut(&mut state) .expect("sole readiness state") - .set_dependency_evaluator(Arc::new(FixedEvaluator( - DependencyReport::from_results( - TimedOutcome::new(PostgresOutcome::Success, Duration::from_millis(3)), - TimedOutcome::new(RedisOutcome::Success, Duration::from_millis(2)), - TimedOutcome::new( - DeletionCatalogOutcome::Success, - Duration::from_millis(1), - ), - Duration::from_millis(3), - ), - ))); + .set_dependency_evaluator(Arc::new(DelayedEvaluator { + report: ready_report(), + started: Arc::clone(&sample_started), + release: Arc::clone(&release_sample), + })); start_dependency_sampler_and_completion_publisher( Arc::clone(&state), republish_interval, ); + sample_started.notified().await; + for _ in 0..3 { + tokio::time::advance(republish_interval).await; + tokio::task::yield_now().await; + } + assert_eq!( + sample_completion_metric_value_from_scrape(&handle.render()), + None, + "republisher ticks must not fabricate an epoch before the first completion" + ); + + release_sample.notify_one(); + let first = wait_for_sample_completion_scrape_value(&handle, |value| value > 0).await; state.dependency_sampler_cancel.cancel(); + tokio::time::resume(); tokio::time::sleep(timeout + Duration::from_millis(200)).await; assert_eq!( From b96aa84dd43df6bea3061c71437a5d015a798d27 Mon Sep 17 00:00:00 2001 From: tornquist Date: Fri, 25 Sep 2026 18:59:14 +0000 Subject: [PATCH 17/17] test(relay): bound readiness sampler startup wait Signed-off-by: tornquist Co-authored-by: Codex Signed-off-by: tornquist --- crates/buzz-relay/src/readiness.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/crates/buzz-relay/src/readiness.rs b/crates/buzz-relay/src/readiness.rs index 624a3649adc..f39689f20ac 100644 --- a/crates/buzz-relay/src/readiness.rs +++ b/crates/buzz-relay/src/readiness.rs @@ -1277,7 +1277,9 @@ mod tests { republish_interval, ); - sample_started.notified().await; + tokio::time::timeout(Duration::from_secs(5), sample_started.notified()) + .await + .expect("dependency sampler must start its first sample within 5 seconds"); for _ in 0..3 { tokio::time::advance(republish_interval).await; tokio::task::yield_now().await;