diff --git a/Cargo.lock b/Cargo.lock index 9162869b2275..d182f2c8d024 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -9704,6 +9704,7 @@ dependencies = [ "ic-test-utilities", "ic-test-utilities-consensus", "ic-test-utilities-logger", + "ic-test-utilities-metrics", "ic-test-utilities-registry", "ic-test-utilities-state", "ic-test-utilities-time", diff --git a/rs/consensus/src/consensus/metrics.rs b/rs/consensus/src/consensus/metrics.rs index da3a46065bf5..495039e71192 100644 --- a/rs/consensus/src/consensus/metrics.rs +++ b/rs/consensus/src/consensus/metrics.rs @@ -190,7 +190,7 @@ pub(crate) struct FinalizerMetrics { pub canister_http_out_of_cycles_delivered: IntCounter, pub canister_http_async_receipts_delivered: IntCounter, pub canister_http_flexible_candid_failures: IntCounter, - pub canister_http_flexible_errors_delivered: IntCounter, + pub canister_http_flexible_errors_delivered: IntCounterVec, pub canister_http_payload_bytes_delivered: Histogram, } @@ -313,9 +313,10 @@ impl FinalizerMetrics { "canister_http_flexible_candid_failures", "Total number of flexible canister http responses skipped due to candid encoding/decoding failures", ), - canister_http_flexible_errors_delivered: metrics_registry.int_counter( + canister_http_flexible_errors_delivered: metrics_registry.int_counter_vec( "canister_http_flexible_errors_delivered", - "Total number of flexible canister http errors delivered", + "Total number of flexible canister http errors delivered, by kind of error", + &["type"], ), canister_http_payload_bytes_delivered: metrics_registry.histogram( "canister_http_payload_bytes_delivered", @@ -387,8 +388,11 @@ impl FinalizerMetrics { self.canister_http_flexible_candid_failures .inc_by(flexible_ok_candid_failures + flexible_error_candid_failures); - self.canister_http_flexible_errors_delivered - .inc_by(batch_stats.canister_http.flexible_errors as u64); + for (kind, count) in &batch_stats.canister_http.flexible_errors { + self.canister_http_flexible_errors_delivered + .with_label_values(&[kind]) + .inc_by(*count as u64); + } self.canister_http_payload_bytes_delivered .observe(batch_stats.canister_http.payload_bytes as f64); diff --git a/rs/https_outcalls/consensus/BUILD.bazel b/rs/https_outcalls/consensus/BUILD.bazel index 1d1c466d6915..8e62b4b26963 100644 --- a/rs/https_outcalls/consensus/BUILD.bazel +++ b/rs/https_outcalls/consensus/BUILD.bazel @@ -74,6 +74,7 @@ rust_test( "//rs/test_utilities", "//rs/test_utilities/consensus", "//rs/test_utilities/logger", + "//rs/test_utilities/metrics", "//rs/test_utilities/registry", "//rs/test_utilities/state", "//rs/test_utilities/time", diff --git a/rs/https_outcalls/consensus/Cargo.toml b/rs/https_outcalls/consensus/Cargo.toml index ed858456ecf0..e084e3362d0d 100644 --- a/rs/https_outcalls/consensus/Cargo.toml +++ b/rs/https_outcalls/consensus/Cargo.toml @@ -41,6 +41,7 @@ ic-registry-subnet-features = { path = "../../registry/subnet_features" } ic-test-utilities = { path = "../../test_utilities" } ic-test-utilities-consensus = { path = "../../test_utilities/consensus" } ic-test-utilities-logger = { path = "../../test_utilities/logger" } +ic-test-utilities-metrics = { path = "../../test_utilities/metrics" } ic-test-utilities-registry = { path = "../../test_utilities/registry" } ic-test-utilities-state = { path = "../../test_utilities/state" } ic-test-utilities-time = { path = "../../test_utilities/time" } diff --git a/rs/https_outcalls/consensus/src/metrics.rs b/rs/https_outcalls/consensus/src/metrics.rs index 73772a0805df..3309c0a1dd72 100644 --- a/rs/https_outcalls/consensus/src/metrics.rs +++ b/rs/https_outcalls/consensus/src/metrics.rs @@ -1,7 +1,10 @@ //! This module contains metric structs for components of the canister http feature use ic_metrics::{MetricsRegistry, buckets::decimal_buckets}; -use prometheus::{HistogramVec, IntCounter, IntGauge}; +use prometheus::{HistogramVec, IntCounter, IntCounterVec, IntGauge}; + +/// The label whose value names the kind of event or error that was counted. +const LABEL_TYPE: &str = "type"; pub struct CanisterHttpPoolManagerMetrics { /// Records the time it took to perform an operation @@ -17,6 +20,10 @@ pub struct CanisterHttpPoolManagerMetrics { pub shares_validated: IntCounter, /// A count of the total number of shares marked invalid. pub shares_marked_invalid: IntCounter, + /// Notable, but expected events observed by the pool manager, by kind. + pool_manager_events: IntCounterVec, + /// Operations the pool manager failed to perform, by kind. + pool_manager_errors: IntCounterVec, } impl CanisterHttpPoolManagerMetrics { @@ -43,9 +50,29 @@ impl CanisterHttpPoolManagerMetrics { ), shares_marked_invalid: metrics_registry.int_counter( "canister_http_shares_marked_invalid", "A count of the total number of shares marked invalid." - ) + ), + pool_manager_events: metrics_registry.int_counter_vec( + "canister_http_pool_manager_events", + "Notable, but expected events observed by the pool manager, by kind.", + &[LABEL_TYPE], + ), + pool_manager_errors: metrics_registry.int_counter_vec( + "canister_http_pool_manager_errors", + "Canister http pool manager related errors, by kind.", + &[LABEL_TYPE], + ), } } + + /// Records a notable, but expected event of the given kind. + pub(crate) fn observe_pool_manager_event(&self, label: &str) { + self.pool_manager_events.with_label_values(&[label]).inc(); + } + + /// Records a failed operation of the given kind. + pub(crate) fn observe_pool_manager_error(&self, label: &str) { + self.pool_manager_errors.with_label_values(&[label]).inc(); + } } pub struct CanisterHttpPayloadBuilderMetrics { @@ -60,6 +87,8 @@ pub struct CanisterHttpPayloadBuilderMetrics { /// The number of times the initial spent exceeds the limit under /// legacy pricing. pub initial_spent_exceeds_limit: IntCounter, + /// The number of payloads that hit the max response limit. + pub max_responses_per_block_reached: IntCounter, } impl CanisterHttpPayloadBuilderMetrics { @@ -83,7 +112,11 @@ impl CanisterHttpPayloadBuilderMetrics { initial_spent_exceeds_limit: metrics_registry.int_counter( "canister_http_initial_spent_exceeds_limit", "The number of times the initial spent exceeds the limit under legacy pricing." - ) + ), + max_responses_per_block_reached: metrics_registry.int_counter( + "canister_http_max_responses_per_block_reached", + "The number of payloads that hit the per-block limit on canister http responses." + ), } } } diff --git a/rs/https_outcalls/consensus/src/payload_builder.rs b/rs/https_outcalls/consensus/src/payload_builder.rs index 98fb55a55a11..add1d084cff7 100644 --- a/rs/https_outcalls/consensus/src/payload_builder.rs +++ b/rs/https_outcalls/consensus/src/payload_builder.rs @@ -87,7 +87,7 @@ pub struct CanisterHttpBatchStats { pub single_signature_responses: usize, pub flexible_ok_responses: usize, pub flexible_ok_responses_candid_failures: usize, - pub flexible_errors: usize, + pub flexible_errors: BTreeMap<&'static str, usize>, pub flexible_errors_candid_failures: usize, pub payload_bytes: usize, } @@ -239,6 +239,27 @@ impl CanisterHttpPayloadBuilderImpl { accumulated_size += candidate_size; } } + let groups = shares_by_callback_id.get(callback_id); + let (groups, success, reject) = groups.map_or((0, 0, 0), |groups| { + let (mut success, mut reject) = (0, 0); + for share in groups.values().flatten() { + if share.content.is_reject() { + reject += 1; + } else { + success += 1; + } + } + (groups.len(), success, reject) + }); + warn!( + self.log, + "CanisterHttpPayloadBuilder: timeout for callback_id {callback_id} \ + with {groups} groups ({success} success, {reject} reject), pricing {:?}, \ + replication {:?}, refund status {:?}", + request.pricing_version, + request.replication, + request.refund_status + ); continue; } if responses_included >= CANISTER_HTTP_MAX_RESPONSES_PER_BLOCK { @@ -425,6 +446,16 @@ impl CanisterHttpPayloadBuilderImpl { } } + if responses_included >= CANISTER_HTTP_MAX_RESPONSES_PER_BLOCK { + warn!( + every_n_seconds => 15, + self.log, + "CanisterHttpPayloadBuilder: reached max responses per block ({})", + CANISTER_HTTP_MAX_RESPONSES_PER_BLOCK + ); + self.metrics.max_responses_per_block_reached.inc(); + } + CanisterHttpPayload { responses, timeouts, @@ -1496,9 +1527,10 @@ impl // Timeouts carry no shares and produce no spend report. FlexibleCanisterHttpError::Timeout { .. } => None, }; + let kind = error.kind(); match flexible_error_into_consensus_response(error) { Some(consensus_response) => { - stats.flexible_errors += 1; + *stats.flexible_errors.entry(kind).or_default() += 1; consensus_responses.push(consensus_response); if let Some(report) = report { spent.initial.push(report); diff --git a/rs/https_outcalls/consensus/src/payload_builder/tests.rs b/rs/https_outcalls/consensus/src/payload_builder/tests.rs index 12d91af824c3..c6eb0ddb08c7 100644 --- a/rs/https_outcalls/consensus/src/payload_builder/tests.rs +++ b/rs/https_outcalls/consensus/src/payload_builder/tests.rs @@ -3577,7 +3577,7 @@ fn flexible_error_into_messages_timeout() { assert_eq!(responses.len(), 1); assert_eq!(responses[0].callback, callback_id); - assert_eq!(stats.flexible_errors, 1); + assert_eq!(stats.flexible_errors, BTreeMap::from([("timeout", 1)])); assert_eq!(stats.flexible_errors_candid_failures, 0); // A flexible timeout carries no full response body, hence reports no spend. assert!(spent.initial.is_empty()); @@ -3621,7 +3621,10 @@ fn flexible_error_into_messages_too_many_rejects() { assert_eq!(responses.len(), 1); assert_eq!(responses[0].callback, callback_id); - assert_eq!(stats.flexible_errors, 1); + assert_eq!( + stats.flexible_errors, + BTreeMap::from([("too_many_rejects", 1)]) + ); assert_eq!(stats.flexible_errors_candid_failures, 0); let Payload::Data(ref data) = responses[0].payload else { @@ -3676,7 +3679,10 @@ fn flexible_error_into_messages_responses_too_large() { assert_eq!(responses.len(), 1); assert_eq!(responses[0].callback, callback_id); - assert_eq!(stats.flexible_errors, 1); + assert_eq!( + stats.flexible_errors, + BTreeMap::from([("responses_too_large", 1)]) + ); assert_eq!(stats.flexible_errors_candid_failures, 0); // A responses-too-large error delivers no body (consensus cost zero), so it // reports the sum of its seen shares' per-replica spend. Here every share @@ -6509,7 +6515,10 @@ fn flexible_outcall_is_out_of_cycles_when_allowances_are_exhausted() { let (responses, spent, stats) = CanisterHttpPayloadBuilderImpl::into_messages( &payload_to_bytes_max_4mb(payload.clone()), ); - assert_eq!(stats.flexible_errors, 1); + assert_eq!( + stats.flexible_errors, + BTreeMap::from([("out_of_cycles", 1)]) + ); assert_eq!(responses.len(), 1); let Payload::Data(ref data) = responses[0].payload else { panic!("Expected Payload::Data, got {:?}", responses[0].payload); diff --git a/rs/https_outcalls/consensus/src/pool_manager.rs b/rs/https_outcalls/consensus/src/pool_manager.rs index 84d9c5546801..31bfd5372adb 100644 --- a/rs/https_outcalls/consensus/src/pool_manager.rs +++ b/rs/https_outcalls/consensus/src/pool_manager.rs @@ -192,11 +192,15 @@ impl CanisterHttpPoolManagerImpl { } }; - allowed_boundary_nodes - .unwrap_or_else(|e| { - warn!(self.log, "Failed to get API boundary node IDs: {:?}", e); - Vec::new() - }) + let allowed_boundary_nodes = allowed_boundary_nodes.unwrap_or_else(|e| { + warn!(self.log, "Failed to get API boundary node IDs: {:?}", e); + self.metrics + .observe_pool_manager_error("boundary_node_ids_lookup_failed"); + Vec::new() + }); + let num_boundary_nodes = allowed_boundary_nodes.len(); + + let addrs = allowed_boundary_nodes .into_iter() .filter_map(|id| { self.registry_client @@ -222,7 +226,13 @@ impl CanisterHttpPoolManagerImpl { }) .map(|http_info| format!("socks5h://[{0}]:1080", http_info.ip_addr)) }) - .collect::>() + .collect::>(); + + if addrs.len() != num_boundary_nodes { + self.metrics + .observe_pool_manager_error("socks_proxy_addrs_unresolved"); + } + addrs } /// Returns whether `node_id` belongs to the committee responsible for the @@ -253,6 +263,8 @@ impl CanisterHttpPoolManagerImpl { context.registry_version, e ); + self.metrics + .observe_pool_manager_error("committee_membership_lookup_failed"); }), Replication::NonReplicated(delegated_node_id) => Ok(node_id == delegated_node_id), Replication::Flexible { committee, .. } => Ok(committee.contains(node_id)), @@ -321,9 +333,16 @@ impl CanisterHttpPoolManagerImpl { warn!( self.log, "Failed to add canister http request to queue {:?}", err - ) + ); + // The id is not cached, so the request is retried next round. + self.metrics.observe_pool_manager_error(match err { + SendError::Full(_) => "adapter_queue_full", + SendError::BrokenConnection => "adapter_connection_broken", + }); } else { self.requested_id_cache.borrow_mut().insert(*id); + self.metrics + .observe_pool_manager_event("request_sent_to_adapter"); } } } @@ -348,21 +367,35 @@ impl CanisterHttpPoolManagerImpl { match self.http_adapter_shim.lock().unwrap().try_receive() { Err(TryReceiveError::Empty) => break, Ok((response, payment_receipt)) => { + self.metrics + .observe_pool_manager_event("adapter_response_received"); // Drop the response if its context is no longer present in the replicated state. // We continue gossiping a share even if a response to the context has already // been delivered, in order to report the amount of cycles spent. - let Some(context) = active_contexts - .get(&response.id) - .or_else(|| delivered_contexts.get(&response.id)) - else { - warn!( - self.log, - "Dropping http response for request ID {}: \ - corresponding context is no longer in the replicated state.", - response.id, - ); - self.requested_id_cache.borrow_mut().remove(&response.id); - continue; + let context = match active_contexts.get(&response.id) { + Some(context) => context, + None => match delivered_contexts.get(&response.id) { + Some(context) => { + // Consensus already answered this request; we only sign a + // share to report the cycles we spent on it. + self.metrics + .observe_pool_manager_event("response_for_delivered_context"); + context + } + None => { + warn!( + self.log, + "Dropping http response for request ID {}: \ + corresponding context is no longer in the replicated state.", + response.id, + ); + self.metrics.observe_pool_manager_event( + "response_dropped_context_timed_out", + ); + self.requested_id_cache.borrow_mut().remove(&response.id); + continue; + } + }, }; let receipt_share = CanisterHttpResponseReceipt { @@ -381,6 +414,10 @@ impl CanisterHttpPoolManagerImpl { self.log, "Http Response for request ID {} is too large: {}", response.id, err ); + // Our own adapter produced a response no honest replica could + // have produced, so no peer would accept a share for it. + self.metrics + .observe_pool_manager_error("own_response_too_large"); continue; } @@ -391,8 +428,10 @@ impl CanisterHttpPoolManagerImpl { self.replica_config.node_id, context.registry_version, ) - .map_err(|err| error!(self.log, "Failed to sign http response {}", err)) - { + .map_err(|err| { + error!(self.log, "Failed to sign http response {}", err); + self.metrics.observe_pool_manager_error("sign_share_failed"); + }) { signature } else { continue; @@ -454,6 +493,8 @@ impl CanisterHttpPoolManagerImpl { // Reject shares from different replica versions if !is_current_protocol_version(share.content.replica_version()) { + self.metrics + .observe_pool_manager_event("share_dropped_unknown_version"); return Some(CanisterHttpChangeAction::RemoveUnvalidated(share.clone())); } @@ -468,6 +509,8 @@ impl CanisterHttpPoolManagerImpl { .get(&share.content.id()) .or_else(|| delivered_contexts.get(&share.content.id())) else { + self.metrics + .observe_pool_manager_event("share_dropped_unknown_context"); return Some(CanisterHttpChangeAction::RemoveUnvalidated(share.clone())); }; @@ -657,6 +700,7 @@ pub mod test { use ic_registry_keys::{make_api_boundary_node_record_key, make_node_record_key}; use ic_replicated_state::metadata_state::subnet_call_context_manager::SubnetCallContext; use ic_test_utilities_logger::with_test_replica_logger; + use ic_test_utilities_metrics::{fetch_int_counter_vec, metric_vec}; use ic_test_utilities_types::ids::{node_test_id, subnet_test_id}; use ic_types::CountBytes; use ic_types::crypto::crypto_hash; @@ -1047,6 +1091,7 @@ pub mod test { let shim: Arc> = Arc::new(Mutex::new(Box::new(shim_mock))); + let metrics_registry = MetricsRegistry::new(); let pool_manager = CanisterHttpPoolManagerImpl::new( state_manager as Arc<_>, shim, @@ -1055,7 +1100,7 @@ pub mod test { replica_config, SubnetType::Application, Arc::clone(®istry) as Arc<_>, - MetricsRegistry::new(), + metrics_registry.clone(), log, ); @@ -1065,6 +1110,15 @@ pub mod test { // The share is dropped silently (removed, not marked invalid). assert_eq!(changes.len(), 1); assert_matches!(&changes[0], CanisterHttpChangeAction::RemoveUnvalidated(_)); + // Dropping it is expected during an upgrade, so it is not an error. + assert_eq!( + metric_vec(&[(&[("type", "share_dropped_unknown_version")], 1)]), + fetch_int_counter_vec(&metrics_registry, "canister_http_pool_manager_events") + ); + assert!( + fetch_int_counter_vec(&metrics_registry, "canister_http_pool_manager_errors") + .is_empty() + ); }) }); } @@ -1168,6 +1222,7 @@ pub mod test { let shim: Arc> = Arc::new(Mutex::new(Box::new(shim_mock))); + let metrics_registry = MetricsRegistry::new(); let pool_manager = CanisterHttpPoolManagerImpl::new( state_manager as Arc<_>, shim, @@ -1176,7 +1231,7 @@ pub mod test { replica_config, SubnetType::Application, Arc::clone(®istry) as Arc<_>, - MetricsRegistry::new(), + metrics_registry.clone(), log, ); diff --git a/rs/types/types/src/batch/canister_http.rs b/rs/types/types/src/batch/canister_http.rs index 5be3422e593b..a23037a764ee 100644 --- a/rs/types/types/src/batch/canister_http.rs +++ b/rs/types/types/src/batch/canister_http.rs @@ -116,6 +116,17 @@ impl FlexibleCanisterHttpError { } } + /// The kind of error this is, as a short stable name. Used as a metric + /// label, so the returned set of values must stay small and fixed. + pub fn kind(&self) -> &'static str { + match self { + Self::Timeout { .. } => "timeout", + Self::ResponsesTooLarge { .. } => "responses_too_large", + Self::TooManyRejects { .. } => "too_many_rejects", + Self::OutOfCycles { .. } => "out_of_cycles", + } + } + /// The signed receipts this error carries whose response body is *not* part of /// the payload: all of the evidence behind [`Self::ResponsesTooLarge`] and /// [`Self::OutOfCycles`], and the extra shares funding a