From 0e283a9de171a99f7dc7f115d4a30700aac99632 Mon Sep 17 00:00:00 2001 From: Chet Nichols III Date: Mon, 13 Jul 2026 19:04:33 -0700 Subject: [PATCH] feat: surface the swallowed errors across the fleet A handful of fallible operations were silent in both pipelines -- no log, no metric -- so observability couldn't see them at all, including a rack health-report persist failure discarded with `Err(_) => { /* will retry */ }`. Every one now logs, and the one whose failure rate is worth watching also counts. Primary callouts are: - `carbide_dsx_exchange_consumer_health_report_persist_failures_total` -- the dsx health-report persist failure now emits a single framework event that both warns and counts (the rack id and error ride as log context). It's the one failure here worth a rate, so it's the one that gets a counter. - The silently-dropped failures now warn: the read-only and error-unwinding `txn.rollback()` drops across the handlers, now funneled through a shared `Transaction::rollback_or_log` helper; the DHCP TLS-material reads that fall back to a built-in default cert; the empty product serial fed into DPF; the preingestion subprocess kill/wait drops; and the health log-file flush, rotate, and prune drops. Each keeps its crate's logging convention, and the error-unwinding rollbacks log without clobbering the original error being returned. - The site-explorer `bmc_reset_count` counted attempts, not successes: the ipmitool reset dropped its result with `.ok()` while the counter ticked regardless. A shared `record_bmc_reset_outcome` now increments only on success and logs the failure, and both the ipmitool and Redfish paths route through it -- so the counter finally means what its name says, with no rename. The MQTT state-change send drop the issue pointed at turned out to be a test mock; the production send path already logs and meters every outcome, so nothing was left silent there. Tests added! This supports https://github.com/NVIDIA/infra-controller/issues/3179 --- crates/api-core/src/handlers/credential.rs | 3 +- .../api-core/src/handlers/expected_machine.rs | 6 +- crates/api-core/src/handlers/instance.rs | 3 +- crates/api-core/src/handlers/power_shelf.rs | 3 +- crates/api-core/src/handlers/rack.rs | 2 +- crates/api-core/src/handlers/switch.rs | 3 +- crates/api-db/src/lib.rs | 25 +++ crates/dhcp/src/lib.rs | 27 ++- crates/dsx-exchange-consumer/Cargo.toml | 1 + .../src/health_updater.rs | 12 +- crates/dsx-exchange-consumer/src/metrics.rs | 27 +++ .../tests/metric_exposition.rs | 53 +++++- crates/health/src/sink/log_file.rs | 26 ++- crates/machine-controller/src/handler/dpf.rs | 7 + crates/preingestion-manager/src/lib.rs | 55 +++++- crates/site-explorer/src/lib.rs | 180 +++++++++++++++--- crates/site-explorer/src/metrics.rs | 2 +- docs/observability/core_metrics.md | 2 +- 18 files changed, 378 insertions(+), 59 deletions(-) diff --git a/crates/api-core/src/handlers/credential.rs b/crates/api-core/src/handlers/credential.rs index b65efadd96..5be550a942 100644 --- a/crates/api-core/src/handlers/credential.rs +++ b/crates/api-core/src/handlers/credential.rs @@ -526,7 +526,8 @@ pub(crate) async fn get_switch_nvos_credentials( db::ObjectColumnFilter::One(db::switch::IdColumn, &switch_id), ) .await?; - let _ = txn.rollback().await; + txn.rollback_or_log("read-only load of switch for credential lookup") + .await; let switch = switches .first() diff --git a/crates/api-core/src/handlers/expected_machine.rs b/crates/api-core/src/handlers/expected_machine.rs index 610564baf3..3c42b7d199 100644 --- a/crates/api-core/src/handlers/expected_machine.rs +++ b/crates/api-core/src/handlers/expected_machine.rs @@ -590,7 +590,8 @@ async fn process_batch_operations( } }, Err(e) => { - let _ = txn.rollback().await; + txn.rollback_or_log("expected-machine write after operation failure") + .await; results.push(build_failure_result(id, format!("Operation failed: {}", e))); } } @@ -624,7 +625,8 @@ async fn process_batch_operations( ) .await { - let _ = txn.rollback().await; + txn.rollback_or_log("expected-machine write after operation failure") + .await; return Err(e); } results.push(build_success_result(machine_for_result)); diff --git a/crates/api-core/src/handlers/instance.rs b/crates/api-core/src/handlers/instance.rs index ee0a7a01c6..a214fd8328 100644 --- a/crates/api-core/src/handlers/instance.rs +++ b/crates/api-core/src/handlers/instance.rs @@ -278,7 +278,8 @@ pub(crate) async fn find_by_ids( for snapshot in snapshots.into_iter() { instances.push(snapshot_to_instance(snapshot)?); } - let _ = txn.rollback().await; + txn.rollback_or_log("read-only load of instances by id") + .await; Ok(Response::new(rpc::InstanceList { instances })) } diff --git a/crates/api-core/src/handlers/power_shelf.rs b/crates/api-core/src/handlers/power_shelf.rs index 9ba8c4329a..fb7f4cf14a 100644 --- a/crates/api-core/src/handlers/power_shelf.rs +++ b/crates/api-core/src/handlers/power_shelf.rs @@ -138,7 +138,8 @@ pub async fn find_by_ids( ) .await?; - let _ = txn.rollback().await; + txn.rollback_or_log("read-only load of power shelves by id") + .await; let power_shelves = convert_power_shelves(power_shelf_list)?; diff --git a/crates/api-core/src/handlers/rack.rs b/crates/api-core/src/handlers/rack.rs index da3bacbe1d..acbd26bb42 100644 --- a/crates/api-core/src/handlers/rack.rs +++ b/crates/api-core/src/handlers/rack.rs @@ -125,7 +125,7 @@ pub async fn find_by_ids( result.push(rack.into()); } - let _ = txn.rollback().await; + txn.rollback_or_log("read-only load of racks by id").await; Ok(Response::new(rpc::RackList { racks: result })) } diff --git a/crates/api-core/src/handlers/switch.rs b/crates/api-core/src/handlers/switch.rs index cba187c282..0702b910b5 100644 --- a/crates/api-core/src/handlers/switch.rs +++ b/crates/api-core/src/handlers/switch.rs @@ -176,7 +176,8 @@ pub async fn find_by_ids( .map(|row| (row.switch_id, row)) .collect(); - let _ = txn.rollback().await; + txn.rollback_or_log("read-only load of switches by id") + .await; let switches: Vec = switch_list .into_iter() diff --git a/crates/api-db/src/lib.rs b/crates/api-db/src/lib.rs index d55ae36ae6..b98910d1d1 100644 --- a/crates/api-db/src/lib.rs +++ b/crates/api-db/src/lib.rs @@ -686,6 +686,31 @@ impl<'a> Transaction<'a> { }) } + // This function can just async when + // https://github.com/rust-lang/rust/issues/110011 will be + // implemented + /// Roll back the transaction, logging a warning tagged with `context` if + /// the rollback itself fails, rather than propagating -- for read-only or + /// cleanup paths where the caller can't act on a rollback error but must + /// not swallow it. + #[track_caller] + pub fn rollback_or_log( + self, + context: &'static str, + ) -> Pin + Send + 'a>> { + let loc = Location::caller(); + Box::pin(async move { + if let Err(e) = self + .inner + .rollback() + .await + .map_err(|e| DatabaseError::txn_rollback(e, loc)) + { + tracing::warn!(error = %e, context, "Failed to roll back transaction"); + } + }) + } + pub fn as_pgconn(&mut self) -> &mut sqlx::PgConnection { &mut self.inner } diff --git a/crates/dhcp/src/lib.rs b/crates/dhcp/src/lib.rs index d5d7458b26..2825829dd8 100644 --- a/crates/dhcp/src/lib.rs +++ b/crates/dhcp/src/lib.rs @@ -75,12 +75,27 @@ impl Default for CarbideDhcpContext { Self { api_endpoint: "https://[::1]:1079".to_string(), nameservers: vec![Ipv4Addr::new(1, 1, 1, 1)], - forge_root_ca_path: std::env::var("FORGE_ROOT_CAFILE_PATH") - .unwrap_or_else(|_| tls_default::ROOT_CA.to_string()), - forge_client_cert_path: std::env::var("FORGE_CLIENT_CERT_PATH") - .unwrap_or_else(|_| tls_default::CLIENT_CERT.to_string()), - forge_client_key_path: std::env::var("FORGE_CLIENT_KEY_PATH") - .unwrap_or_else(|_| tls_default::CLIENT_KEY.to_string()), + forge_root_ca_path: std::env::var("FORGE_ROOT_CAFILE_PATH").unwrap_or_else(|e| { + log::warn!( + "FORGE_ROOT_CAFILE_PATH unset or unreadable ({e}); falling back to the built-in default root CA at {}", + tls_default::ROOT_CA + ); + tls_default::ROOT_CA.to_string() + }), + forge_client_cert_path: std::env::var("FORGE_CLIENT_CERT_PATH").unwrap_or_else(|e| { + log::warn!( + "FORGE_CLIENT_CERT_PATH unset or unreadable ({e}); falling back to the built-in default client certificate at {}", + tls_default::CLIENT_CERT + ); + tls_default::CLIENT_CERT.to_string() + }), + forge_client_key_path: std::env::var("FORGE_CLIENT_KEY_PATH").unwrap_or_else(|e| { + log::warn!( + "FORGE_CLIENT_KEY_PATH unset or unreadable ({e}); falling back to the built-in default client key at {}", + tls_default::CLIENT_KEY + ); + tls_default::CLIENT_KEY.to_string() + }), ntpservers: vec![ Ipv4Addr::new(172, 20, 0, 24), Ipv4Addr::new(172, 20, 0, 26), diff --git a/crates/dsx-exchange-consumer/Cargo.toml b/crates/dsx-exchange-consumer/Cargo.toml index 7a4b0f0658..8a4384472b 100644 --- a/crates/dsx-exchange-consumer/Cargo.toml +++ b/crates/dsx-exchange-consumer/Cargo.toml @@ -62,6 +62,7 @@ carbide-version = { path = "../version" } [dev-dependencies] carbide-instrument = { path = "../instrument", features = ["test-support"] } carbide-test-support = { path = "../test-support" } +tracing = { workspace = true } [lints] workspace = true diff --git a/crates/dsx-exchange-consumer/src/health_updater.rs b/crates/dsx-exchange-consumer/src/health_updater.rs index f71f2c4800..d2512478f9 100644 --- a/crates/dsx-exchange-consumer/src/health_updater.rs +++ b/crates/dsx-exchange-consumer/src/health_updater.rs @@ -30,7 +30,7 @@ use crate::ConsumerMetrics; use crate::api_client::{HEALTH_REPORT_SOURCE, RackHealthReportSink}; use crate::config::CacheConfig; use crate::messages::{FaultValue, LeakMetadata, LeakPointType, ValueMessage}; -use crate::metrics::{MessageDeduplicated, MessageProcessed}; +use crate::metrics::{HealthReportPersistFailed, MessageDeduplicated, MessageProcessed}; use crate::mqtt_consumer::MqttMessage; /// Health status updater that processes MQTT messages and updates the API. @@ -212,8 +212,14 @@ impl HealthUpdater { Ok(_) => { emit(MessageProcessed); } - Err(_) => { - // API call failed - will retry on next message + Err(e) => { + // Surface the persist failure and count it. The value re-arrives + // on the next message, so processing still retries -- but the + // drop is now visible instead of silently discarded. + emit(HealthReportPersistFailed { + rack_id: metadata.rack_id.clone(), + error: e.to_string(), + }); } } } diff --git a/crates/dsx-exchange-consumer/src/metrics.rs b/crates/dsx-exchange-consumer/src/metrics.rs index 7221496ef4..d0de66d9e2 100644 --- a/crates/dsx-exchange-consumer/src/metrics.rs +++ b/crates/dsx-exchange-consumer/src/metrics.rs @@ -119,6 +119,33 @@ pub struct MessageDropped; )] pub struct MessageDeduplicated; +/// A rack health report could not be persisted to the Carbide API -- either a +/// coolant-leak override insert or its clearing removal failed. The value +/// re-arrives on the next message, so processing still retries, but a rising +/// rate is safety-relevant: leak state is not reaching the API. Logs the +/// failure and moves the counter from one `emit`. +/// +/// Unlike the grandfathered counters above, this is a new metric, so it uses +/// the standard checked name: the exporter appends the single `_total` that +/// `/metrics` shows. +#[derive(Event)] +#[event( + name = "carbide_dsx_exchange_consumer_health_report_persist_failures_total", + component = "nico-dsx-exchange-consumer", + log = warn, + metric = counter, + message = "Failed to persist rack health report", + describe = "Number of rack health report persist failures against the Carbide API" +)] +pub struct HealthReportPersistFailed { + /// The rack whose health report could not be persisted. + #[context] + pub rack_id: String, + /// The API error that prevented the persist. + #[context] + pub error: String, +} + /// Consumer metrics that remain hand-rolled OpenTelemetry counters. /// /// Only `alerts_detected` stays here: its `point_type` label is a diff --git a/crates/dsx-exchange-consumer/tests/metric_exposition.rs b/crates/dsx-exchange-consumer/tests/metric_exposition.rs index a080b73da8..c7f70457e8 100644 --- a/crates/dsx-exchange-consumer/tests/metric_exposition.rs +++ b/crates/dsx-exchange-consumer/tests/metric_exposition.rs @@ -20,15 +20,18 @@ //! registering and the OTel Prometheus exporter appends exactly one, so //! `/metrics` shows one suffix, not the historical doubled `_total_total`. //! -//! One test in its own binary (its own process-global registry) keeps the -//! `counter_delta` measurements deterministic: the crate's other unit tests -//! emit these same events, but from a different test process. +//! These tests live in their own binary (its own process-global registry) to +//! keep the `counter_delta` measurements deterministic: the crate's other unit +//! tests emit these same events -- the message counters here, and the +//! health-report persist failure below -- but from a different test process, so +//! they cannot advance a shared counter between a test's baseline and delta. use carbide_dsx_exchange_consumer::metrics::{ - MessageDeduplicated, MessageDropped, MessageProcessed, MessageReceived, + HealthReportPersistFailed, MessageDeduplicated, MessageDropped, MessageProcessed, + MessageReceived, }; use carbide_instrument::emit; -use carbide_instrument::testing::{MetricsCapture, capture_logs}; +use carbide_instrument::testing::{CapturedLog, MetricsCapture, capture_logs}; /// Emitting each event once moves exactly its counter, under the single /// `_total` name the OTel Prometheus exporter produces (the framework strips @@ -81,3 +84,43 @@ fn message_events_expose_single_total_names_and_are_metric_only() { // remain. assert!(logs.is_empty(), "events must be metric-only: {logs:?}"); } + +/// A persist failure writes the WARN line carrying the rack id and error, and +/// moves `carbide_dsx_exchange_consumer_health_report_persist_failures_total` once -- +/// the "log it AND count it" the safety-relevant drop needs. Isolated here +/// because `health_updater`'s failure-path unit tests emit this same event +/// without a `MetricsCapture`; from a shared process they could advance the +/// zero-label counter between this test's baseline and delta. +#[test] +fn health_report_persist_failed_logs_warn_and_counts() { + let metrics = MetricsCapture::start(); + let logs = capture_logs(|| { + emit(HealthReportPersistFailed { + rack_id: "rack-42".to_string(), + error: "API call failed: deadline exceeded".to_string(), + }); + }); + + assert_eq!(logs.len(), 1); + assert_eq!(logs[0].level, tracing::Level::WARN); + assert_eq!(logs[0].message, "Failed to persist rack health report"); + fn field<'a>(log: &'a CapturedLog, name: &str) -> Option<&'a str> { + log.fields + .iter() + .find(|(key, _)| key == name) + .map(|(_, value)| value.as_str()) + } + assert_eq!(field(&logs[0], "rack_id"), Some("rack-42")); + assert_eq!( + field(&logs[0], "error"), + Some("API call failed: deadline exceeded") + ); + + assert_eq!( + metrics.counter_delta( + "carbide_dsx_exchange_consumer_health_report_persist_failures_total", + &[], + ), + 1.0 + ); +} diff --git a/crates/health/src/sink/log_file.rs b/crates/health/src/sink/log_file.rs index 94e00d085f..e9b0933d52 100644 --- a/crates/health/src/sink/log_file.rs +++ b/crates/health/src/sink/log_file.rs @@ -208,14 +208,18 @@ impl SyncLogFileWriter { tracing::info!(size = self.current_size, "rotating log file"); // flush and drop the current file handle before renaming - if let Some(mut file) = self.current_file.take() { - let _ = file.flush(); + if let Some(mut file) = self.current_file.take() + && let Err(e) = file.flush() + { + tracing::warn!(error = %e, "failed to flush log file before rotation"); } let current_path = self.log_path(); if self.max_backups == 0 { - let _ = fs::remove_file(¤t_path); + if let Err(e) = fs::remove_file(¤t_path) { + tracing::warn!(error = %e, path = %current_path.display(), "failed to remove current log file during rotation"); + } } else { self.shift_backups(¤t_path); } @@ -229,19 +233,25 @@ impl SyncLogFileWriter { for i in (1..self.max_backups).rev() { let from = self.rotated_path(i); let to = self.rotated_path(i + 1); - if from.exists() { - let _ = fs::rename(&from, &to); + if from.exists() + && let Err(e) = fs::rename(&from, &to) + { + tracing::warn!(error = %e, from = %from.display(), to = %to.display(), "failed to shift rotated log file"); } } // current -> .1 let backup = self.rotated_path(1); - let _ = fs::rename(current_path, &backup); + if let Err(e) = fs::rename(current_path, &backup) { + tracing::warn!(error = %e, from = %current_path.display(), to = %backup.display(), "failed to rotate current log file to backup"); + } // prune the oldest backup beyond the limit let oldest = self.rotated_path(self.max_backups + 1); - if oldest.exists() { - let _ = fs::remove_file(&oldest); + if oldest.exists() + && let Err(e) = fs::remove_file(&oldest) + { + tracing::warn!(error = %e, path = %oldest.display(), "failed to prune oldest rotated log file"); } } } diff --git a/crates/machine-controller/src/handler/dpf.rs b/crates/machine-controller/src/handler/dpf.rs index a26e8f7cde..2c1d41cc95 100644 --- a/crates/machine-controller/src/handler/dpf.rs +++ b/crates/machine-controller/src/handler/dpf.rs @@ -195,6 +195,13 @@ async fn create_and_register_dpudevices_and_dpunode( .and_then(|x| x.dmi_data.as_ref()) .map(|x| x.product_serial.as_str()) .unwrap_or_default(); + if serial_number.is_empty() { + tracing::warn!( + dpu_machine_id = %dpu.id, + host_machine_id = %state.host_snapshot.id, + "DPU product serial is missing; registering DPU device with DPF using an empty serial" + ); + } let device_info = carbide_dpf::DpuDeviceInfo { device_id: dpf_id(dpu)?, dpu_bmc_ip: bmc_ip(dpu)?, diff --git a/crates/preingestion-manager/src/lib.rs b/crates/preingestion-manager/src/lib.rs index a101c33f34..3a1cb7b572 100644 --- a/crates/preingestion-manager/src/lib.rs +++ b/crates/preingestion-manager/src/lib.rs @@ -2157,10 +2157,50 @@ impl PreingestionManagerStatic { } }; + /// Which capture setup failed, forcing the subprocess cleanup. + enum CaptureFailure { + Stdout, + Stderr, + } + + impl std::fmt::Display for CaptureFailure { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str(match self { + CaptureFailure::Stdout => "STDOUT capture failure", + CaptureFailure::Stderr => "STDERR capture failure", + }) + } + } + + // Kill then reap `child`, warning -- but not failing -- if either + // step errors. `context` names which capture setup failed, rendered + // via its `Display`. + async fn kill_and_reap( + child: &mut tokio::process::Child, + address: &str, + context: CaptureFailure, + ) { + if let Err(e) = child.kill().await { + tracing::warn!( + %address, + %context, + error = %e, + "Upgrade script cleanup: failed to kill subprocess" + ); + } + if let Err(e) = child.wait().await { + tracing::warn!( + %address, + %context, + error = %e, + "Upgrade script cleanup: failed to reap subprocess" + ); + } + } + let Some(stdout) = cmd.stdout.take() else { tracing::error!("Upgrade script {address} STDOUT creation failed"); - let _ = cmd.kill().await; - let _ = cmd.wait().await; + kill_and_reap(&mut cmd, &address, CaptureFailure::Stdout).await; upgrade_script_state.completed(address, false); return; }; @@ -2168,8 +2208,7 @@ impl PreingestionManagerStatic { let Some(stderr) = cmd.stderr.take() else { tracing::error!("Upgrade script {address} STDERR creation failed"); - let _ = cmd.kill().await; - let _ = cmd.wait().await; + kill_and_reap(&mut cmd, &address, CaptureFailure::Stderr).await; upgrade_script_state.completed(address, false); return; }; @@ -2187,7 +2226,13 @@ impl PreingestionManagerStatic { while let Some(line) = lines.next_line().await.unwrap_or(None) { tracing::info!("Upgrade script {address} {line}"); } - let _ = tokio::join!(thread); + if let Err(e) = thread.await { + tracing::warn!( + %address, + error = %e, + "Upgrade script STDERR logging task did not complete cleanly" + ); + } match cmd.wait().await { Err(e) => { diff --git a/crates/site-explorer/src/lib.rs b/crates/site-explorer/src/lib.rs index cced6bad5e..d04de7db4e 100644 --- a/crates/site-explorer/src/lib.rs +++ b/crates/site-explorer/src/lib.rs @@ -296,6 +296,23 @@ pub struct SiteExplorer { // rms_client: Option>, } +/// Which transport a BMC reset was issued through, rendered as the `method` log +/// field on [`SiteExplorer::record_bmc_reset_outcome`]. +#[derive(Debug, Clone, Copy)] +enum BmcResetMethod { + Ipmitool, + Redfish, +} + +impl std::fmt::Display for BmcResetMethod { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str(match self { + BmcResetMethod::Ipmitool => "ipmitool", + BmcResetMethod::Redfish => "redfish", + }) + } +} + impl SiteExplorer { const ITERATION_WORK_KEY: &'static str = "SiteExplorer::run_single_iteration"; const SITE_EXPLORER_HEALTH_REPORT_WRITE_BATCH_SIZE: usize = 500; @@ -2545,6 +2562,27 @@ impl SiteExplorer { Ok(index) } + /// Record the outcome of a BMC-reset attempt: count only a reset that + /// actually happened (so `bmc_reset_count` tracks successes, not attempts) + /// and log the failure otherwise. Returns whether the reset succeeded. + fn record_bmc_reset_outcome( + outcome: SiteExplorerResult<()>, + via: BmcResetMethod, + address: IpAddr, + metrics: &mut SiteExplorationMetrics, + ) -> bool { + match outcome { + Ok(()) => { + metrics.bmc_reset_count += 1; + true + } + Err(err) => { + tracing::error!(%address, method = %via, error = %err, "Site Explorer failed to reset BMC"); + false + } + } + } + pub async fn handle_redfish_error( &self, endpoint: &Endpoint<'_>, @@ -2700,34 +2738,23 @@ impl SiteExplorer { } if time_since_redfish_bmc_reset > reset_rate_limit - && self - .redfish_reset_bmc(endpoint) - .await - .map_err(|err| { - tracing::error!( - "Site Explorer failed to reset BMC {} through redfish: {}", - endpoint.address, - err - ) - }) - .is_ok() + && Self::record_bmc_reset_outcome( + self.redfish_reset_bmc(endpoint).await, + BmcResetMethod::Redfish, + endpoint.address, + metrics, + ) { - metrics.bmc_reset_count += 1; return; } if time_since_ipmitool_bmc_reset > reset_rate_limit { - self.ipmitool_reset_bmc(endpoint) - .await - .map_err(|err| { - tracing::error!( - "Site Explorer failed to reset BMC {} through ipmitool: {}", - endpoint.address, - err - ) - }) - .ok(); - metrics.bmc_reset_count += 1; + Self::record_bmc_reset_outcome( + self.ipmitool_reset_bmc(endpoint).await, + BmcResetMethod::Ipmitool, + endpoint.address, + metrics, + ); } } @@ -3908,6 +3935,113 @@ mod tests { assert_eq!(u64_to_mac(mac_to_u64(mac)), mac); } + /// The BMC-reset counter tracks resets that happened: a successful reset + /// moves `bmc_reset_count`, a failed reset leaves it and logs the failure + /// instead. This pins that semantics -- the one the ipmitool path used to + /// get wrong, counting every attempt -- across both transports, and checks + /// the failure log carries the transport, address, and error. + #[test] + fn bmc_reset_counter_counts_successes_not_attempts() { + use carbide_instrument::testing::{CapturedLog, capture_logs}; + + /// One reset outcome to record. A success moves `bmc_reset_count` and + /// logs nothing; a failure leaves the counter and emits the ERROR line, + /// whose `error` field is `expect_error` (`None` on the success rows). + struct Case { + name: &'static str, + method: BmcResetMethod, + outcome: SiteExplorerResult<()>, + expect_succeeded: bool, + expect_count: usize, + expect_error: Option<&'static str>, + } + + let addr: IpAddr = "127.0.0.1".parse().unwrap(); + + let cases = [ + Case { + name: "ipmitool success counts, logs nothing", + method: BmcResetMethod::Ipmitool, + outcome: Ok(()), + expect_succeeded: true, + expect_count: 1, + expect_error: None, + }, + Case { + name: "ipmitool failure logs, does not count", + method: BmcResetMethod::Ipmitool, + outcome: Err(SiteExplorerError::internal( + "simulated ipmitool failure".to_string(), + )), + expect_succeeded: false, + expect_count: 0, + expect_error: Some("Internal error: simulated ipmitool failure"), + }, + Case { + name: "redfish success counts, logs nothing", + method: BmcResetMethod::Redfish, + outcome: Ok(()), + expect_succeeded: true, + expect_count: 1, + expect_error: None, + }, + Case { + name: "redfish failure logs, does not count", + method: BmcResetMethod::Redfish, + outcome: Err(SiteExplorerError::internal( + "simulated redfish failure".to_string(), + )), + expect_succeeded: false, + expect_count: 0, + expect_error: Some("Internal error: simulated redfish failure"), + }, + ]; + + fn field<'a>(log: &'a CapturedLog, name: &str) -> Option<&'a str> { + log.fields + .iter() + .find(|(key, _)| key == name) + .map(|(_, value)| value.as_str()) + } + + for case in cases { + let Case { + name, + method, + outcome, + expect_succeeded, + expect_count, + expect_error, + } = case; + + // Fresh metrics per case so the counter reads as this outcome alone. + let mut metrics = SiteExplorationMetrics::new(); + let mut succeeded = false; + let logs = capture_logs(|| { + succeeded = + SiteExplorer::record_bmc_reset_outcome(outcome, method, addr, &mut metrics); + }); + + assert_eq!(succeeded, expect_succeeded, "{name}"); + assert_eq!(metrics.bmc_reset_count, expect_count, "{name}"); + + match expect_error { + None => assert!(logs.is_empty(), "{name}: a success must not log: {logs:?}"), + Some(expect_error) => { + assert_eq!(logs.len(), 1, "{name}"); + let log = &logs[0]; + let method = method.to_string(); + let address = addr.to_string(); + assert_eq!(log.level, tracing::Level::ERROR, "{name}"); + assert_eq!(log.message, "Site Explorer failed to reset BMC", "{name}"); + assert_eq!(field(log, "method"), Some(method.as_str()), "{name}"); + assert_eq!(field(log, "address"), Some(address.as_str()), "{name}"); + assert_eq!(field(log, "error"), Some(expect_error), "{name}"); + } + } + } + } + #[test] fn u64_to_mac_discards_high_bits() { // High 16 bits set must not leak into the MAC bytes. diff --git a/crates/site-explorer/src/metrics.rs b/crates/site-explorer/src/metrics.rs index 89cd8c2994..326a6b4980 100644 --- a/crates/site-explorer/src/metrics.rs +++ b/crates/site-explorer/src/metrics.rs @@ -673,7 +673,7 @@ impl SiteExplorerInstruments { let metrics = shared_metrics.clone(); meter .u64_observable_gauge("carbide_site_explorer_bmc_reset_count") - .with_description("Number of BMC resets initiated in the last SiteExplorer run") + .with_description("Number of successful BMC resets in the last SiteExplorer run") .with_callback(move |observer| { metrics.if_available(|metrics, attrs| { observer.observe(metrics.bmc_reset_count as u64, attrs); diff --git a/docs/observability/core_metrics.md b/docs/observability/core_metrics.md index 60769dfcc0..bf30fbad3e 100644 --- a/docs/observability/core_metrics.md +++ b/docs/observability/core_metrics.md @@ -147,7 +147,7 @@ This file contains a list of metrics exported by NVIDIA Infra Controller (NICo). carbide_site_exploration_expected_machines_sku_countgaugeNumber of expected machines by SKU ID and device type carbide_site_exploration_identified_managed_hosts_countgaugeNumber of Host+DPU pairs identified in the last SiteExplorer run carbide_site_explorer_bmc_password_rotations_totalcounterNumber of BMC root password rotations onto the site-wide credential, by outcome -carbide_site_explorer_bmc_reset_countgaugeNumber of BMC resets initiated in the last SiteExplorer run +carbide_site_explorer_bmc_reset_countgaugeNumber of successful BMC resets in the last SiteExplorer run carbide_site_explorer_create_machinesgaugeWhether site-explorer machine creation is enabled (1) or disabled (0) carbide_site_explorer_create_machines_latency_millisecondshistogramThe time it took to perform create_machines inside site-explorer carbide_site_explorer_created_machines_countgaugeNumber of machine pairs created by Site Explorer after identification