From 25f1442030e7367653aa912aa276a6e7dd206c1c Mon Sep 17 00:00:00 2001 From: durch Date: Thu, 23 Oct 2025 20:50:44 +0200 Subject: [PATCH] more metrics --- Cargo.lock | 2 + common/credential-verification/Cargo.toml | 1 + .../credential-verification/src/ecash/mod.rs | 6 +- .../src/ecash/state.rs | 4 + common/credential-verification/src/lib.rs | 37 +++++++- common/wireguard/Cargo.toml | 1 + common/wireguard/src/peer_controller.rs | 17 +++- gateway/src/node/lp_listener/handler.rs | 92 +++++++++++++++++++ gateway/src/node/lp_listener/mod.rs | 17 +++- gateway/src/node/lp_listener/registration.rs | 35 ++++++- 10 files changed, 204 insertions(+), 8 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5f641942d0..155b684397 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5618,6 +5618,7 @@ dependencies = [ "nym-ecash-contract-common", "nym-gateway-requests", "nym-gateway-storage", + "nym-metrics", "nym-task", "nym-validator-client", "rand 0.8.5", @@ -7650,6 +7651,7 @@ dependencies = [ "nym-crypto", "nym-gateway-requests", "nym-gateway-storage", + "nym-metrics", "nym-network-defaults", "nym-node-metrics", "nym-task", diff --git a/common/credential-verification/Cargo.toml b/common/credential-verification/Cargo.toml index e85589eaae..b2ff4e0872 100644 --- a/common/credential-verification/Cargo.toml +++ b/common/credential-verification/Cargo.toml @@ -30,5 +30,6 @@ nym-credentials-interface = { path = "../credentials-interface" } nym-ecash-contract-common = { path = "../cosmwasm-smart-contracts/ecash-contract" } nym-gateway-requests = { path = "../gateway-requests" } nym-gateway-storage = { path = "../gateway-storage" } +nym-metrics = { path = "../nym-metrics" } nym-task = { path = "../task" } nym-validator-client = { path = "../client-libs/validator-client" } diff --git a/common/credential-verification/src/ecash/mod.rs b/common/credential-verification/src/ecash/mod.rs index a5eac14867..45d55635ad 100644 --- a/common/credential-verification/src/ecash/mod.rs +++ b/common/credential-verification/src/ecash/mod.rs @@ -59,9 +59,13 @@ impl traits::EcashManager for EcashManager { .verify(aggregated_verification_key) .map_err(|err| match err { CompactEcashError::ExpirationDateSignatureValidity => { + nym_metrics::inc!("ecash_verification_failures_invalid_date_signature"); EcashTicketError::MalformedTicketInvalidDateSignatures } - _ => EcashTicketError::MalformedTicket, + _ => { + nym_metrics::inc!("ecash_verification_failures_signature"); + EcashTicketError::MalformedTicket + } })?; self.insert_pay_info(credential.pay_info.into(), insert_index) diff --git a/common/credential-verification/src/ecash/state.rs b/common/credential-verification/src/ecash/state.rs index 389ee98c68..78cabf7a95 100644 --- a/common/credential-verification/src/ecash/state.rs +++ b/common/credential-verification/src/ecash/state.rs @@ -222,9 +222,13 @@ impl SharedState { RwLockReadGuard::try_map(guard, |data| data.get(&epoch_id).map(|d| &d.master_key)) { trace!("we already had cached api clients for epoch {epoch_id}"); + nym_metrics::inc!("ecash_verification_key_cache_hits"); return Ok(mapped); } + // Cache miss - need to fetch and set epoch data + nym_metrics::inc!("ecash_verification_key_cache_misses"); + let write_guard = self.set_epoch_data(epoch_id).await?; let guard = write_guard.downgrade(); diff --git a/common/credential-verification/src/lib.rs b/common/credential-verification/src/lib.rs index f306867d98..eb5d94d27c 100644 --- a/common/credential-verification/src/lib.rs +++ b/common/credential-verification/src/lib.rs @@ -8,6 +8,7 @@ use nym_credentials::ecash::utils::{EcashTime, cred_exp_date, ecash_today}; use nym_credentials_interface::{Bandwidth, ClientTicket, TicketType}; use nym_gateway_requests::models::CredentialSpendingRequest; use std::sync::Arc; +use std::time::Instant; use time::{Date, OffsetDateTime}; use tracing::*; @@ -19,6 +20,11 @@ mod client_bandwidth; pub mod ecash; pub mod error; +// Histogram buckets for ecash verification duration (in seconds) +const ECASH_VERIFICATION_DURATION_BUCKETS: &[f64] = &[ + 0.001, 0.005, 0.01, 0.05, 0.1, 0.5, 1.0, 2.0, 5.0, +]; + pub struct CredentialVerifier { credential: CredentialSpendingRequest, ecash_verifier: Arc, @@ -62,6 +68,7 @@ impl CredentialVerifier { .await?; if spent { trace!("the credential has already been spent before at this gateway"); + nym_metrics::inc!("ecash_verification_failures_double_spending"); return Err(Error::BandwidthCredentialAlreadySpent); } Ok(()) @@ -103,6 +110,9 @@ impl CredentialVerifier { } pub async fn verify(&mut self) -> Result { + let start = Instant::now(); + nym_metrics::inc!("ecash_verification_attempts"); + let received_at = OffsetDateTime::now_utc(); let spend_date = ecash_today(); @@ -111,15 +121,36 @@ impl CredentialVerifier { let credential_type = TicketType::try_from_encoded(self.credential.data.payment.t_type)?; if self.credential.data.payment.spend_value != 1 { + nym_metrics::inc!("ecash_verification_failures_multiple_tickets"); return Err(Error::MultipleTickets); } - self.check_credential_spending_date(spend_date.ecash_date())?; + if let Err(e) = self.check_credential_spending_date(spend_date.ecash_date()) { + nym_metrics::inc!("ecash_verification_failures_invalid_spend_date"); + return Err(e); + } + self.check_local_db_for_double_spending(&serial_number) .await?; // TODO: do we HAVE TO do it? - self.cryptographically_verify_ticket().await?; + let verify_result = self.cryptographically_verify_ticket().await; + + // Track verification duration + let duration = start.elapsed().as_secs_f64(); + nym_metrics::add_histogram_obs!( + "ecash_verification_duration_seconds", + duration, + ECASH_VERIFICATION_DURATION_BUCKETS + ); + + // Track epoch ID - use dynamic metric name via registry + let epoch_id = self.credential.data.epoch_id; + let epoch_metric = format!("nym_credential_verification_ecash_epoch_{}_verifications", epoch_id); + nym_metrics::metrics_registry().maybe_register_and_inc(&epoch_metric, None); + + // Check verification result after timing + verify_result?; let ticket_id = self.store_received_ticket(received_at).await?; self.async_verify_ticket(ticket_id); @@ -133,6 +164,8 @@ impl CredentialVerifier { .increase_bandwidth(bandwidth, cred_exp_date()) .await?; + nym_metrics::inc!("ecash_verification_success"); + Ok(self .bandwidth_storage_manager .client_bandwidth diff --git a/common/wireguard/Cargo.toml b/common/wireguard/Cargo.toml index e98e5fc27d..43732f4fbb 100644 --- a/common/wireguard/Cargo.toml +++ b/common/wireguard/Cargo.toml @@ -37,6 +37,7 @@ nym-credential-verification = { path = "../credential-verification" } nym-crypto = { path = "../crypto", features = ["asymmetric"] } nym-gateway-storage = { path = "../gateway-storage" } nym-gateway-requests = { path = "../gateway-requests" } +nym-metrics = { path = "../nym-metrics" } nym-network-defaults = { path = "../network-defaults" } nym-task = { path = "../task" } nym-wireguard-types = { path = "../wireguard-types" } diff --git a/common/wireguard/src/peer_controller.rs b/common/wireguard/src/peer_controller.rs index e9e4f78f2d..67d9802a94 100644 --- a/common/wireguard/src/peer_controller.rs +++ b/common/wireguard/src/peer_controller.rs @@ -138,6 +138,8 @@ impl PeerController { // Function that should be used for peer removal, to handle both storage and kernel interaction pub async fn remove_peer(&mut self, key: &Key) -> Result<()> { + nym_metrics::inc!("wg_peer_removal_attempts"); + self.ecash_verifier .storage() .remove_wireguard_peer(&key.to_string()) @@ -145,9 +147,12 @@ impl PeerController { self.bw_storage_managers.remove(key); let ret = self.wg_api.remove_peer(key); if ret.is_err() { + nym_metrics::inc!("wg_peer_removal_failed"); log::error!( "Wireguard peer could not be removed from wireguard kernel module. Process should be restarted so that the interface is reset." ); + } else { + nym_metrics::inc!("wg_peer_removal_success"); } Ok(ret?) } @@ -177,7 +182,15 @@ impl PeerController { } async fn handle_add_request(&mut self, peer: &Peer) -> Result<()> { - self.wg_api.configure_peer(peer)?; + nym_metrics::inc!("wg_peer_addition_attempts"); + + // Try to configure WireGuard peer + if let Err(e) = self.wg_api.configure_peer(peer) { + nym_metrics::inc!("wg_peer_addition_failed"); + nym_metrics::inc!("wg_config_errors_total"); + return Err(e.into()); + } + let bandwidth_storage_manager = SharedBandwidthStorageManager::new( Arc::new(RwLock::new( Self::generate_bandwidth_manager(self.ecash_verifier.storage(), &peer.public_key) @@ -205,6 +218,8 @@ impl PeerController { handle.run().await; log::debug!("Peer handle shut down for {public_key}"); }); + + nym_metrics::inc!("wg_peer_addition_success"); Ok(()) } diff --git a/gateway/src/node/lp_listener/handler.rs b/gateway/src/node/lp_listener/handler.rs index 71f08f930a..ee63fa16bc 100644 --- a/gateway/src/node/lp_listener/handler.rs +++ b/gateway/src/node/lp_listener/handler.rs @@ -33,10 +33,59 @@ const LP_DURATION_BUCKETS: &[f64] = &[ 10.0, // 10s ]; +// Histogram buckets for LP connection lifecycle duration +// LP connections can be very short (registration only: ~1s) or very long (dVPN sessions: hours/days) +// Covers full range from seconds to 24 hours +const LP_CONNECTION_DURATION_BUCKETS: &[f64] = &[ + 1.0, // 1 second + 5.0, // 5 seconds + 10.0, // 10 seconds + 30.0, // 30 seconds + 60.0, // 1 minute + 300.0, // 5 minutes + 600.0, // 10 minutes + 1800.0, // 30 minutes + 3600.0, // 1 hour + 7200.0, // 2 hours + 14400.0, // 4 hours + 28800.0, // 8 hours + 43200.0, // 12 hours + 86400.0, // 24 hours +]; + +/// Connection lifecycle statistics tracking +struct ConnectionStats { + /// When the connection started + start_time: std::time::Instant, + /// Total bytes received (including protocol framing) + bytes_received: u64, + /// Total bytes sent (including protocol framing) + bytes_sent: u64, +} + +impl ConnectionStats { + fn new() -> Self { + Self { + start_time: std::time::Instant::now(), + bytes_received: 0, + bytes_sent: 0, + } + } + + fn record_bytes_received(&mut self, bytes: usize) { + self.bytes_received += bytes as u64; + } + + fn record_bytes_sent(&mut self, bytes: usize) { + self.bytes_sent += bytes as u64; + } +} + pub struct LpConnectionHandler { stream: TcpStream, remote_addr: SocketAddr, state: LpHandlerState, + stats: ConnectionStats, } impl LpConnectionHandler { @@ -45,6 +94,7 @@ impl LpConnectionHandler { stream, remote_addr, state, + stats: ConnectionStats::new(), } } @@ -71,6 +121,8 @@ impl LpConnectionHandler { Err(e) => { // Track ClientHello failures (timestamp validation, protocol errors, etc.) inc!("lp_client_hello_failed"); + // Emit lifecycle metrics before returning + self.emit_lifecycle_metrics(false); return Err(e); } }; @@ -99,6 +151,8 @@ impl LpConnectionHandler { Err(e) => { inc!("lp_handshakes_failed"); inc!("lp_errors_handshake"); + // Emit lifecycle metrics before returning + self.emit_lifecycle_metrics(false); return Err(e); } }; @@ -127,6 +181,8 @@ impl LpConnectionHandler { { warn!("Failed to send LP response to {}: {}", self.remote_addr, e); inc!("lp_errors_send_response"); + // Emit lifecycle metrics before returning + self.emit_lifecycle_metrics(false); return Err(e); } @@ -142,6 +198,9 @@ impl LpConnectionHandler { ); } + // Emit lifecycle metrics on graceful completion + self.emit_lifecycle_metrics(true); + Ok(()) } @@ -339,6 +398,9 @@ impl LpConnectionHandler { GatewayError::LpConnectionError(format!("Failed to read packet data: {}", e)) })?; + // Track bytes received (4 byte header + packet data) + self.stats.record_bytes_received(4 + packet_len); + parse_lp_packet(&packet_buf) .map_err(|e| GatewayError::LpProtocolError(format!("Failed to parse LP packet: {}", e))) } @@ -372,8 +434,38 @@ impl LpConnectionHandler { GatewayError::LpConnectionError(format!("Failed to flush stream: {}", e)) })?; + // Track bytes sent (4 byte header + packet data) + self.stats.record_bytes_sent(4 + packet_buf.len()); + Ok(()) } + + /// Emit connection lifecycle metrics + fn emit_lifecycle_metrics(&self, graceful: bool) { + use nym_metrics::inc_by; + + // Track connection duration + let duration = self.stats.start_time.elapsed().as_secs_f64(); + add_histogram_obs!( + "lp_connection_duration_seconds", + duration, + LP_CONNECTION_DURATION_BUCKETS + ); + + // Track bytes transferred + inc_by!( + "lp_connection_bytes_received_total", + self.stats.bytes_received as i64 + ); + inc_by!("lp_connection_bytes_sent_total", self.stats.bytes_sent as i64); + + // Track completion type + if graceful { + inc!("lp_connections_completed_gracefully"); + } else { + inc!("lp_connections_completed_with_error"); + } + } } // Extension trait for LpSession to create packets diff --git a/gateway/src/node/lp_listener/mod.rs b/gateway/src/node/lp_listener/mod.rs index fef19c06dd..f26490206a 100644 --- a/gateway/src/node/lp_listener/mod.rs +++ b/gateway/src/node/lp_listener/mod.rs @@ -46,6 +46,13 @@ // ## Error Categorization Metrics // - lp_errors_wg_peer_registration: Counter for WireGuard peer registration failures // +// ## Connection Lifecycle Metrics (in handler.rs) +// - lp_connection_duration_seconds: Histogram of connection duration from start to end (buckets: 1s to 24h) +// - lp_connection_bytes_received_total: Counter for total bytes received including protocol framing +// - lp_connection_bytes_sent_total: Counter for total bytes sent including protocol framing +// - lp_connections_completed_gracefully: Counter for connections that completed successfully +// - lp_connections_completed_with_error: Counter for connections that terminated with an error +// // ## Usage Example // To view metrics, the nym-metrics registry automatically collects all metrics. // They can be exported via Prometheus format using the metrics endpoint. @@ -271,9 +278,17 @@ impl LpListener { let metrics = self.handler_state.metrics.clone(); self.shutdown.try_spawn_named( async move { - if let Err(e) = handler.handle().await { + let result = handler.handle().await; + + // Handler emits lifecycle metrics internally on success + // For errors, we need to emit them here since handler is consumed + if let Err(e) = result { warn!("LP handler error for {}: {}", remote_addr, e); + // Note: metrics are emitted in handle() for graceful path + // On error path, handle() returns early without emitting + // So we track errors here } + // Decrement connection counter on exit metrics.network.lp_connection_closed(); }, diff --git a/gateway/src/node/lp_listener/registration.rs b/gateway/src/node/lp_listener/registration.rs index 378fe5a86a..acf8b51413 100644 --- a/gateway/src/node/lp_listener/registration.rs +++ b/gateway/src/node/lp_listener/registration.rs @@ -39,6 +39,21 @@ const LP_REGISTRATION_DURATION_BUCKETS: &[f64] = &[ 30.0, // 30s ]; +// Histogram buckets for WireGuard peer controller channel latency +// Measures time to send request and receive response from peer controller +// Expected: 1ms-100ms for normal operations, up to 2s for slow conditions +const WG_CONTROLLER_LATENCY_BUCKETS: &[f64] = &[ + 0.001, // 1ms + 0.005, // 5ms + 0.01, // 10ms + 0.05, // 50ms + 0.1, // 100ms + 0.25, // 250ms + 0.5, // 500ms + 1.0, // 1s + 2.0, // 2s +]; + /// Prepare bandwidth storage for a client async fn credential_storage_preparation( ecash_verifier: Arc, @@ -281,6 +296,7 @@ async fn register_wg_peer( // Allocate IP addresses for the client // TODO: Proper IP pool management - for now use random in private range + inc!("wg_ip_allocation_attempts"); let last_octet = { let mut rng = rand::thread_rng(); (rng.next_u32() % 254 + 1) as u8 @@ -288,6 +304,7 @@ async fn register_wg_peer( let client_ipv4 = Ipv4Addr::new(10, 1, 0, last_octet); let client_ipv6 = Ipv6Addr::new(0xfd00, 0, 0, 0, 0, 0, 0, last_octet as u16); + inc!("wg_ip_allocation_success"); // Create WireGuard peer let mut peer = Peer::new(peer_key.clone()); @@ -303,7 +320,8 @@ async fn register_wg_peer( ]; peer.persistent_keepalive_interval = Some(25); - // Send to WireGuard peer controller + // Send to WireGuard peer controller and track latency + let controller_start = std::time::Instant::now(); let (tx, rx) = oneshot::channel(); wg_controller .send(PeerControlRequest::AddPeer { @@ -313,11 +331,22 @@ async fn register_wg_peer( .await .map_err(|e| GatewayError::InternalError(format!("Failed to send peer request: {}", e)))?; - rx.await + let result = rx + .await .map_err(|e| { GatewayError::InternalError(format!("Failed to receive peer response: {}", e)) })? - .map_err(|e| GatewayError::InternalError(format!("Failed to add peer: {:?}", e)))?; + .map_err(|e| GatewayError::InternalError(format!("Failed to add peer: {:?}", e))); + + // Record peer controller channel latency + let latency = controller_start.elapsed().as_secs_f64(); + add_histogram_obs!( + "wg_peer_controller_channel_latency_seconds", + latency, + WG_CONTROLLER_LATENCY_BUCKETS + ); + + result?; // Store bandwidth allocation and get client_id let client_id = state