diff --git a/Cargo.lock b/Cargo.lock index ac4ea620bb..2f0132b687 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1133,6 +1133,7 @@ dependencies = [ "chrono", "deadpool-redis", "futures-util", + "metrics", "nostr", "redis", "serde", diff --git a/crates/buzz-acp/src/relay.rs b/crates/buzz-acp/src/relay.rs index 2cbb82411f..c56b90d631 100644 --- a/crates/buzz-acp/src/relay.rs +++ b/crates/buzz-acp/src/relay.rs @@ -29,6 +29,9 @@ use std::time::Duration; const EVENT_CHANNEL_CAPACITY_DEFAULT: usize = 256; /// Capacity of the command channel from harness to background task. const CMD_CHANNEL_CAPACITY: usize = 64; +/// Upgrade-response header emitted by buzz-relay for joining client and server +/// diagnostics without exposing a tenant or identity. +const RELAY_CONNECTION_ID_HEADER: &str = "x-buzz-connection-id"; /// Read the event channel capacity from the environment, falling back to the /// compiled-in default. Parsed once at call-site (connect time). @@ -121,7 +124,7 @@ use buzz_core::kind::{ KIND_TYPING_INDICATOR, }; use futures_util::{SinkExt, StreamExt}; -use nostr::{Event, EventBuilder, Keys, Kind, RelayUrl, Tag}; +use nostr::{Event, EventBuilder, Keys, Kind, RelayUrl, Tag, Timestamp}; use serde_json::{json, Value}; use tokio::sync::mpsc; use tokio::time::timeout; @@ -620,7 +623,7 @@ impl HarnessRelay { // jittered backoff. A terminal error (bad URL, bad auth tag, // rejected/invalid signing key) fails immediately — see // `is_terminal_connect_error`. - let (ws, handshake_buffer) = + let (ws, handshake_buffer, relay_connection_id) = retry_initial_connect(|| do_connect(relay_url, keys, auth_tag.as_ref())).await?; let (event_tx, event_rx) = mpsc::channel::>(event_channel_capacity()); @@ -644,6 +647,7 @@ impl HarnessRelay { bg_relay_url, bg_agent_pubkey_hex, bg_auth_tag, + relay_connection_id, ) .await; }); @@ -990,6 +994,15 @@ impl TwoGenDedup { /// State maintained by the background WebSocket task. struct BgState { + /// Opaque connection ID supplied by the relay in the WebSocket upgrade. + /// This joins harness logs to one exact server-side connection without + /// logging message content or client identity. + relay_connection_id: Option, + /// Monotonic socket generation within this harness process. + connection_generation: u64, + /// Relay connection establishment time, used to identify events that + /// predate the current socket and therefore likely arrived via replay. + connected_at: u64, /// Active subscriptions: channel_id → subscription_id string. active_subscriptions: HashMap, /// Most recent `created_at` timestamp seen per channel (for `since` filter). @@ -1078,6 +1091,9 @@ struct BgState { impl BgState { fn new() -> Self { Self { + relay_connection_id: None, + connection_generation: 0, + connected_at: 0, active_subscriptions: HashMap::new(), last_seen: HashMap::new(), seen_ids: TwoGenDedup::new(SEEN_ID_LIMIT), @@ -1102,6 +1118,12 @@ impl BgState { } } + fn note_connection(&mut self, relay_connection_id: Option) { + self.relay_connection_id = relay_connection_id; + self.connection_generation = self.connection_generation.saturating_add(1); + self.connected_at = Timestamp::now().as_secs(); + } + /// Record a received event for dedup and `since` tracking. /// Returns `true` if the event is new (not a duplicate). fn record_event(&mut self, channel_id: Uuid, event: &Event) -> bool { @@ -1557,8 +1579,10 @@ async fn run_background_task( relay_url: String, agent_pubkey_hex: String, auth_tag: Option, + initial_relay_connection_id: Option, ) { let mut state = BgState::new(); + state.note_connection(initial_relay_connection_id); let handshake_ok = process_handshake_buffer( &mut ws, @@ -1822,11 +1846,20 @@ async fn run_background_task( } } Some(Err(e)) => { - warn!("WebSocket error in background task: {e}"); + warn!( + relay_connection_id = state.relay_connection_id.as_deref().unwrap_or("unavailable"), + connection_generation = state.connection_generation, + error = %e, + "WebSocket error in background task" + ); true } None => { - debug!("WebSocket stream ended"); + warn!( + relay_connection_id = state.relay_connection_id.as_deref().unwrap_or("unavailable"), + connection_generation = state.connection_generation, + "WebSocket stream ended without a Close frame" + ); true } }; @@ -1953,7 +1986,12 @@ async fn run_background_task( _ = ping_interval.tick() => { if ping_sent && last_pong.elapsed() > PONG_TIMEOUT { // No pong received after our last ping — connection is dead. - warn!("no pong received within {:?} — connection dead, reconnecting", PONG_TIMEOUT); + warn!( + relay_connection_id = state.relay_connection_id.as_deref().unwrap_or("unavailable"), + connection_generation = state.connection_generation, + timeout_secs = PONG_TIMEOUT.as_secs(), + "no pong received — connection dead, reconnecting" + ); // Use try_send to avoid blocking on backpressure during recovery. let _ = event_tx.try_send(None); match try_autonomous_reconnect( @@ -2156,6 +2194,18 @@ async fn handle_ws_message( let ts = event.created_at.as_secs(); let event_id_hex = event.id.to_hex(); if state.record_event(channel_id, &event) { + let received_at = Timestamp::now().as_secs(); + debug!( + relay_connection_id = state.relay_connection_id.as_deref().unwrap_or("unavailable"), + connection_generation = state.connection_generation, + subscription_id = %subscription_id, + channel_id = %channel_id, + event_id = %event_id_hex, + event_created_at = ts, + delivery_age_secs = received_at.saturating_sub(ts), + event_predates_connection = ts < state.connected_at, + "relay channel event received" + ); let buzz_event = BuzzEvent { channel_id, event: *event, @@ -2390,8 +2440,24 @@ async fn handle_ws_message( } true } - Message::Close(_) => { - debug!("relay sent Close frame"); + Message::Close(frame) => { + match frame { + Some(frame) => warn!( + relay_connection_id = state.relay_connection_id.as_deref().unwrap_or("unavailable"), + connection_generation = state.connection_generation, + close_code = ?frame.code, + close_reason = %frame.reason, + "relay sent Close frame" + ), + None => warn!( + relay_connection_id = state + .relay_connection_id + .as_deref() + .unwrap_or("unavailable"), + connection_generation = state.connection_generation, + "relay sent Close frame without code or reason" + ), + } false } // Binary, Pong, Frame — ignore @@ -2938,9 +3004,18 @@ async fn try_autonomous_reconnect( backoffs.len() ); match do_connect(relay_url, keys, auth_tag).await { - Ok((new_ws, handshake_buffer)) => { + Ok((new_ws, handshake_buffer, relay_connection_id)) => { *ws = new_ws; - info!("autonomous reconnect succeeded (attempt {})", attempt + 1); + state.note_connection(relay_connection_id); + info!( + relay_connection_id = state + .relay_connection_id + .as_deref() + .unwrap_or("unavailable"), + connection_generation = state.connection_generation, + attempt = attempt + 1, + "autonomous reconnect succeeded" + ); let handshake_ok = process_handshake_buffer( ws, handshake_buffer, @@ -3076,9 +3151,18 @@ async fn wait_for_reconnect( loop { info!("attempting relay reconnect to {relay_url}…"); match do_connect(relay_url, keys, auth_tag).await { - Ok((new_ws, handshake_buffer)) => { + Ok((new_ws, handshake_buffer, relay_connection_id)) => { *ws = new_ws; - info!("relay reconnected to {relay_url}"); + state.note_connection(relay_connection_id); + info!( + relay_connection_id = state + .relay_connection_id + .as_deref() + .unwrap_or("unavailable"), + connection_generation = state.connection_generation, + relay_url, + "relay reconnected" + ); let handshake_ok = process_handshake_buffer( ws, handshake_buffer, @@ -3842,16 +3926,24 @@ async fn do_connect( relay_url: &str, keys: &Keys, auth_tag: Option<&nostr::Tag>, -) -> Result<(WsStream, VecDeque), RelayError> { +) -> Result<(WsStream, VecDeque, Option), RelayError> { let parsed = relay_url .parse::() .map_err(|e| RelayError::Http(format!("invalid relay URL: {e}")))?; - let (ws, _response) = tokio::time::timeout(CONNECT_TIMEOUT, connect_async(parsed.as_str())) + let (ws, response) = tokio::time::timeout(CONNECT_TIMEOUT, connect_async(parsed.as_str())) .await .map_err(|_| RelayError::ConnectionClosed)? // timeout → treat as connection failure .map_err(|e| RelayError::WebSocket(Box::new(e)))?; - debug!("connected to relay at {relay_url}"); + let relay_connection_id = response + .headers() + .get(RELAY_CONNECTION_ID_HEADER) + .and_then(|value| value.to_str().ok()) + .map(str::to_owned); + info!( + relay_connection_id = relay_connection_id.as_deref().unwrap_or("unavailable"), + relay_url, "connected to relay" + ); let mut ws = ws; let mut buffer: VecDeque = VecDeque::new(); @@ -3874,7 +3966,7 @@ async fn do_connect( }; debug!("NIP-42 authentication successful (event {event_id})"); - Ok((ws, buffer)) + Ok((ws, buffer, relay_connection_id)) } /// Wait for an `AUTH` challenge from the relay, buffering any other messages. @@ -4400,6 +4492,21 @@ mod tests { ); } + #[test] + fn connection_diagnostics_advance_generation_and_replace_relay_id() { + let mut state = BgState::new(); + + state.note_connection(Some("first".to_string())); + let first_connected_at = state.connected_at; + assert_eq!(state.connection_generation, 1); + assert_eq!(state.relay_connection_id.as_deref(), Some("first")); + + state.note_connection(Some("second".to_string())); + assert_eq!(state.connection_generation, 2); + assert_eq!(state.relay_connection_id.as_deref(), Some("second")); + assert!(state.connected_at >= first_connected_at); + } + #[tokio::test] async fn fresh_reconnect_preserves_gate_until_pending_replay_resumes() { let (mut client, mut server) = test_ws_pair().await; diff --git a/crates/buzz-pubsub/Cargo.toml b/crates/buzz-pubsub/Cargo.toml index 2ee2d6b47d..fb2575fa8c 100644 --- a/crates/buzz-pubsub/Cargo.toml +++ b/crates/buzz-pubsub/Cargo.toml @@ -21,6 +21,7 @@ tracing = { workspace = true } thiserror = { workspace = true } nostr = { workspace = true } futures-util = { workspace = true } +metrics = { workspace = true } [dev-dependencies] tokio = { workspace = true } diff --git a/crates/buzz-pubsub/src/subscriber.rs b/crates/buzz-pubsub/src/subscriber.rs index 88826ed99b..de64cdf7d6 100644 --- a/crates/buzz-pubsub/src/subscriber.rs +++ b/crates/buzz-pubsub/src/subscriber.rs @@ -56,9 +56,15 @@ pub(crate) async fn run_subscriber( // established and ran successfully, so reset backoff to the initial // value — a brief Redis restart should reconnect quickly. backoff_secs = BACKOFF_INITIAL_SECS; + metrics::gauge!("buzz_pubsub_connected").set(0.0); + metrics::counter!("buzz_pubsub_disconnects_total", "reason" => "clean") + .increment(1); tracing::warn!("Redis pub/sub stream ended (clean disconnect) — reconnecting in {backoff_secs}s"); } Err(e) => { + metrics::gauge!("buzz_pubsub_connected").set(0.0); + metrics::counter!("buzz_pubsub_disconnects_total", "reason" => "error") + .increment(1); tracing::error!("Redis pub/sub error: {e} — reconnecting in {backoff_secs}s"); } } @@ -66,6 +72,7 @@ pub(crate) async fn run_subscriber( tokio::time::sleep(Duration::from_secs(backoff_secs)).await; backoff_secs = (backoff_secs * 2).min(BACKOFF_MAX_SECS); + metrics::counter!("buzz_pubsub_reconnect_attempts_total").increment(1); tracing::info!("Attempting to reconnect to Redis pub/sub..."); } } @@ -101,6 +108,9 @@ async fn connect_and_subscribe( topic_count = active_topics.len(), "Redis pub/sub subscriber connected with dynamic scoped subscriptions" ); + metrics::gauge!("buzz_pubsub_connected").set(1.0); + metrics::counter!("buzz_pubsub_connections_total").increment(1); + record_topic_gauges(&desired_topics, &active_topics).await; loop { tokio::select! { @@ -110,6 +120,7 @@ async fn connect_and_subscribe( let channel = topic.redis_channel(); if active_topics.insert(channel.clone()) { sink.subscribe(&channel).await?; + record_topic_gauges(&desired_topics, &active_topics).await; } } SubscriptionCommand::UnsubscribeIfIdle(topic) => { @@ -117,6 +128,7 @@ async fn connect_and_subscribe( let channel = topic.redis_channel(); if active_topics.remove(&channel) { sink.unsubscribe(&channel).await?; + record_topic_gauges(&desired_topics, &active_topics).await; } } } @@ -171,6 +183,17 @@ async fn connect_and_subscribe( } } +async fn record_topic_gauges(desired_topics: &DesiredTopics, active_topics: &HashSet) { + let desired_count = desired_topics + .lock() + .await + .values() + .filter(|count| **count > 0) + .count(); + metrics::gauge!("buzz_pubsub_topics_desired").set(desired_count as f64); + metrics::gauge!("buzz_pubsub_topics_active").set(active_topics.len() as f64); +} + async fn desired_refcount(desired_topics: &DesiredTopics, topic: EventTopicKey) -> usize { desired_topics .lock() diff --git a/crates/buzz-relay/src/connection.rs b/crates/buzz-relay/src/connection.rs index 72a7eb9126..d30d231c7f 100644 --- a/crates/buzz-relay/src/connection.rs +++ b/crates/buzz-relay/src/connection.rs @@ -125,8 +125,8 @@ pub async fn handle_connection( state: Arc, addr: SocketAddr, tenant: TenantContext, + conn_id: Uuid, ) { - let conn_id = Uuid::new_v4(); let cancel = CancellationToken::new(); let community_id = tenant.community(); let registry = Arc::clone(&state.community_connections); diff --git a/crates/buzz-relay/src/handlers/event.rs b/crates/buzz-relay/src/handlers/event.rs index a67797385b..a15c782120 100644 --- a/crates/buzz-relay/src/handlers/event.rs +++ b/crates/buzz-relay/src/handlers/event.rs @@ -305,7 +305,17 @@ pub async fn fan_out_pubsub_event(state: &Arc, channel_event: buzz_pub let matches = state.sub_registry.fan_out_scoped(community_id, &stored); let matches = filter_fanout_by_access(state, community_id, &stored, matches, None).await; + let match_count = matches.len(); + let event_id_hex = stored.event.id.to_hex(); metrics::counter!("buzz_multinode_fanout_total").increment(1); + metrics::histogram!("buzz_multinode_fanout_recipients").record(match_count as f64); + debug!( + event_id = %event_id_hex, + community_id = %community_id, + channel_id = ?channel_id, + match_count, + "Redis event matched local WebSocket subscriptions" + ); if matches.is_empty() { return; } @@ -328,9 +338,17 @@ pub async fn fan_out_pubsub_event(state: &Arc, channel_event: buzz_pub .map(|(conn_id, sub_id)| (*conn_id, sub_id.as_str())), &frames, ); + debug!( + event_id = %event_id_hex, + community_id = %community_id, + channel_id = ?channel_id, + match_count, + drop_count, + "Redis event fan-out completed" + ); if drop_count > 0 { tracing::warn!( - event_id = %stored.event.id.to_hex(), + event_id = %event_id_hex, drop_count, "multi-node fan-out: {drop_count} connection(s) dropped" ); @@ -414,16 +432,41 @@ async fn dispatch_persistent_event_inner( Some(channel_id) => EventTopic::Channel(channel_id), None => EventTopic::Global, }; + let topic_scope = if stored_event.channel_id.is_some() { + "channel" + } else { + "global" + }; state.mark_local_event(tenant.community(), &stored_event.event.id); - if let Err(e) = state + match state .pubsub .publish_event(tenant, topic, &stored_event.event) .await { - state - .local_event_ids - .invalidate(&(tenant.community(), stored_event.event.id.to_bytes())); - warn!(event_id = %event_id_hex, "Redis publish failed: {e}"); + Ok(subscriber_count) => { + metrics::histogram!("buzz_pubsub_event_publish_subscribers", "topic" => topic_scope) + .record(subscriber_count as f64); + if subscriber_count == 0 { + metrics::counter!( + "buzz_pubsub_event_publish_zero_subscribers_total", + "topic" => topic_scope + ) + .increment(1); + } + debug!( + event_id = %event_id_hex, + community_id = %tenant.community(), + channel_id = ?stored_event.channel_id, + subscriber_count, + "event published to Redis" + ); + } + Err(e) => { + state + .local_event_ids + .invalidate(&(tenant.community(), stored_event.event.id.to_bytes())); + warn!(event_id = %event_id_hex, "Redis publish failed: {e}"); + } } let matches = state diff --git a/crates/buzz-relay/src/main.rs b/crates/buzz-relay/src/main.rs index 34dc2dfcf8..2c7dbdf414 100644 --- a/crates/buzz-relay/src/main.rs +++ b/crates/buzz-relay/src/main.rs @@ -6,7 +6,7 @@ use tracing::{error, info, warn}; use tracing_subscriber::{fmt, prelude::*, EnvFilter}; fn log_env_filter(rust_log: Option<&str>) -> EnvFilter { - EnvFilter::new(rust_log.unwrap_or("buzz_relay=info")) + EnvFilter::new(rust_log.unwrap_or("buzz_relay=info,buzz_pubsub=info")) } use uuid::Uuid; @@ -1100,16 +1100,18 @@ mod env_filter_tests { use tracing_subscriber::prelude::*; #[test] - fn unset_enables_datastore_only_for_otel_filter() { + fn unset_enables_relay_and_pubsub_logs_plus_datastore_traces() { let logs = tracing_subscriber::registry().with(log_env_filter(None)); tracing::subscriber::with_default(logs, || { assert!(!tracing::enabled!(target: "buzz_datastore", tracing::Level::INFO)); assert!(tracing::enabled!(target: "buzz_relay", tracing::Level::INFO)); + assert!(tracing::enabled!(target: "buzz_pubsub", tracing::Level::INFO)); }); let otel = tracing_subscriber::registry().with(otel_env_filter(None)); tracing::subscriber::with_default(otel, || { assert!(tracing::enabled!(target: "buzz_datastore", tracing::Level::INFO)); + assert!(tracing::enabled!(target: "buzz_pubsub", tracing::Level::INFO)); }); } diff --git a/crates/buzz-relay/src/router.rs b/crates/buzz-relay/src/router.rs index 400ed1dfe3..c10ba10368 100644 --- a/crates/buzz-relay/src/router.rs +++ b/crates/buzz-relay/src/router.rs @@ -6,9 +6,9 @@ use std::sync::Arc; use axum::{ body::Body, extract::{ConnectInfo, FromRequest, State, WebSocketUpgrade}, - http::{HeaderMap, Request, StatusCode}, + http::{HeaderMap, HeaderValue, Request, StatusCode}, middleware, - response::{IntoResponse, Json}, + response::{IntoResponse, Json, Response}, routing::{get, post, put}, Router, }; @@ -26,6 +26,11 @@ use crate::metrics::track_metrics; use crate::nip11::{nip11_document, relay_info_handler}; use crate::state::AppState; +/// Upgrade-response header used to correlate client diagnostics with the +/// relay's per-connection logs. The value is an opaque, random UUID and carries +/// no tenant or identity information. +pub const RELAY_CONNECTION_ID_HEADER: &str = "x-buzz-connection-id"; + /// Build the axum [`Router`] with all relay routes, middleware, and CORS configuration. /// /// Pure Nostr protocol: WebSocket (NIP-01), HTTP bridge (NIP-98), media (Blossom), @@ -323,9 +328,11 @@ async fn nip11_or_ws_handler( if state.shutting_down.load(Ordering::Relaxed) { return (StatusCode::SERVICE_UNAVAILABLE, "relay restarting").into_response(); } - limit_relay_websocket(ws, max_frame_bytes) - .on_upgrade(move |socket| handle_connection(socket, state, addr, tenant)) - .into_response() + let conn_id = uuid::Uuid::new_v4(); + let response = limit_relay_websocket(ws, max_frame_bytes) + .on_upgrade(move |socket| handle_connection(socket, state, addr, tenant, conn_id)) + .into_response(); + with_relay_connection_id(response, conn_id) } Err(_) => { // Browser requesting HTML and Git web GUI is enabled → serve SPA. @@ -345,6 +352,14 @@ async fn nip11_or_ws_handler( } } +fn with_relay_connection_id(mut response: Response, conn_id: uuid::Uuid) -> Response { + response.headers_mut().insert( + RELAY_CONNECTION_ID_HEADER, + HeaderValue::from_str(&conn_id.to_string()).expect("UUID is a valid header value"), + ); + response +} + fn limit_relay_websocket( ws: WebSocketUpgrade, max_frame_bytes: usize, @@ -460,6 +475,22 @@ mod tests { use super::*; + #[test] + fn websocket_upgrade_exposes_opaque_connection_id() { + let conn_id = uuid::Uuid::new_v4(); + let expected = conn_id.to_string(); + let response = + with_relay_connection_id(StatusCode::SWITCHING_PROTOCOLS.into_response(), conn_id); + + assert_eq!( + response + .headers() + .get(RELAY_CONNECTION_ID_HEADER) + .and_then(|value| value.to_str().ok()), + Some(expected.as_str()) + ); + } + #[test] fn invite_landing_path_requires_exactly_one_nonempty_code_segment() { assert!(is_invite_landing_path("/invite/payload.mac")); diff --git a/crates/buzz-relay/src/telemetry.rs b/crates/buzz-relay/src/telemetry.rs index 91bd92f0f3..f0066dc48d 100644 --- a/crates/buzz-relay/src/telemetry.rs +++ b/crates/buzz-relay/src/telemetry.rs @@ -181,7 +181,7 @@ where /// verbosity must not remove parent spans from exported traces. Set /// `BUZZ_OTEL_FILTER` to override the default targets. pub fn otel_env_filter(configured: Option<&str>) -> EnvFilter { - EnvFilter::new(configured.unwrap_or("buzz_relay=info,buzz_datastore=info")) + EnvFilter::new(configured.unwrap_or("buzz_relay=info,buzz_datastore=info,buzz_pubsub=info")) } /// Build the OTEL [`Resource`] used by the trace provider.