From 9d4bc54890b6d3733cc77ebd708a6920e608d78b Mon Sep 17 00:00:00 2001 From: Chet Nichols III Date: Thu, 9 Jul 2026 10:15:23 -0700 Subject: [PATCH] feat: count firmware update outcomes across every target Firmware updates run for three targets -- host BIOS/BMC, DPU NICs, and SuperNICs -- and none of their outcomes are countable today: starts, completions, and failures live only in log lines, including the "wrong version after attempted update" case that means an update silently didn't take. This makes all of it countable, with each event replacing its site's log line at the historical level (info for progress, warn for failures) and the same information as structured fields. Two counters from `carbide-instrument`: - `carbide_firmware_updates_total{target, phase}` -- started and completed, per target. For hosts both phases fire, so the started-to-completed gap is the in-flight backlog; the DPU-NIC and SuperNIC targets emit started only, with completion visible in their own state flows. - `carbide_firmware_update_failures_total{target, cause}` -- `no_update_match` (a DPU left ready between snapshot and trigger) and `wrong_version_after_update` (the update ran and the firmware version still doesn't match -- the silent-failure case). Notable details: - Started counts only committed triggers: the DPU-NIC emit fires after `txn.commit()`, so an update whose trigger rolled back is a `no_update_match` failure, never a started update, and the started-minus-completed math stays truthful. - Host completion emits once per machine as its update markers clear, replacing one Vec-debug log line with per-machine lines. - A SuperNIC re-counts one started per scout pass while a device stays mismatched -- each pass issues a real apply command, and the sustained rate is the stuck-device signal. Tests added! This supports https://github.com/NVIDIA/infra-controller/issues/3175 Signed-off-by: Chet Nichols III --- .../src/handlers/host_reprovisioning.rs | 11 + crates/api-core/src/handlers/svpc.rs | 19 +- .../dpu_nic_firmware.rs | 64 +++-- .../machine_update_manager/host_firmware.rs | 39 +-- .../src/machine_update_manager/metrics.rs | 235 ++++++++++++++++++ crates/api-core/src/tests/dpu_nic_firmware.rs | 19 ++ docs/observability/core_metrics.md | 2 + 7 files changed, 353 insertions(+), 36 deletions(-) diff --git a/crates/api-core/src/handlers/host_reprovisioning.rs b/crates/api-core/src/handlers/host_reprovisioning.rs index 68966043d1..86b838a76f 100644 --- a/crates/api-core/src/handlers/host_reprovisioning.rs +++ b/crates/api-core/src/handlers/host_reprovisioning.rs @@ -79,6 +79,17 @@ pub(crate) async fn trigger_host_reprovisioning( &machine_id, ) .await?; + // Manual initiations pair with the same completion emit the + // update manager's automatic path gets, keeping the + // started-to-completed gap truthful for every initiator. + carbide_instrument::emit( + crate::machine_update_manager::metrics::FirmwareUpdateProgress { + target: crate::machine_update_manager::metrics::FirmwareUpdateTarget::Host, + phase: crate::machine_update_manager::metrics::FirmwareUpdatePhase::Started, + machine_id, + detail: initiator.to_string(), + }, + ); } Mode::Clear => { db::host_machine_update::clear_host_reprovisioning_request(&mut txn, &machine_id) diff --git a/crates/api-core/src/handlers/svpc.rs b/crates/api-core/src/handlers/svpc.rs index 8aa1d83768..2e3495c9d3 100644 --- a/crates/api-core/src/handlers/svpc.rs +++ b/crates/api-core/src/handlers/svpc.rs @@ -34,6 +34,9 @@ use rpc::protos::mlx_device::MlxDeviceInfo; use tonic::{Request, Response, Status}; use crate::api::{Api, log_request_data}; +use crate::machine_update_manager::metrics::{ + FirmwareUpdatePhase, FirmwareUpdateProgress, FirmwareUpdateTarget, +}; use crate::{CarbideError, CarbideResult}; // Code to handle SVPC specific information. @@ -197,12 +200,16 @@ fn build_apply_firmware_command<'a>( return None; } - tracing::info!( - %machine_id, %pci_name, %part_number, %psid, - observed_fw_version = ?device_info.fw_version_current, - expected_fw_version = %fw_profile.firmware_spec.version, - "firmware version mismatch, applying firmware" - ); + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::SuperNic, + phase: FirmwareUpdatePhase::Started, + machine_id, + detail: format!( + "pci_name={pci_name} part_number={part_number} psid={psid} \ + observed_fw_version={:?} expected_fw_version={}", + device_info.fw_version_current, fw_profile.firmware_spec.version + ), + }); Some(Cow::Borrowed(fw_profile)) })(); diff --git a/crates/api-core/src/machine_update_manager/dpu_nic_firmware.rs b/crates/api-core/src/machine_update_manager/dpu_nic_firmware.rs index 80a79619b1..0003e84655 100644 --- a/crates/api-core/src/machine_update_manager/dpu_nic_firmware.rs +++ b/crates/api-core/src/machine_update_manager/dpu_nic_firmware.rs @@ -29,6 +29,10 @@ use sqlx::PgConnection; use super::dpu_nic_firmware_metrics::DpuNicFirmwareUpdateMetrics; use super::machine_update_module::MachineUpdateModule; +use super::metrics::{ + FirmwareUpdateFailed, FirmwareUpdateFailureCause, FirmwareUpdatePhase, FirmwareUpdateProgress, + FirmwareUpdateTarget, +}; use crate::cfg::file::CarbideConfig; use crate::machine_update_manager::MachineUpdateManager; use crate::{CarbideResult, DatabaseError}; @@ -46,6 +50,14 @@ pub struct DpuNicFirmwareUpdate { /// DPF handle for discovering outdated DPF-managed DPUs. `None` when DPF /// is disabled in config; in that case `find_outdated_dpus_dpf` is not called. pub dpf: Option>, + /// Wrong-version outcomes already counted, keyed by DPU and the version it + /// landed on: the condition persists across manager passes (the update + /// marker stays until an operator intervenes or a new update runs), and a + /// counter must record the outcome once, not once per poll. An entry + /// clears when the DPU's markers clear, so a later attempt that lands + /// wrong again is a new outcome. In-memory: a restart re-reports at most + /// once per stuck DPU. + pub reported_wrong_versions: std::sync::Mutex>, } #[async_trait] @@ -105,11 +117,6 @@ impl MachineUpdateModule for DpuNicFirmwareUpdate { output + format!("{} ({}) ", dpu.dpu_machine_id, dpu.firmware_version).as_str() }); - tracing::info!( - "Starting DPU updates for host {}: {}", - host_machine_id, - dpu_update_string - ); // If the reprovisioning failed to update the database for a // given {dpu,host}_machine_id, log it as a warning and don't // add it to updates_started. @@ -124,11 +131,13 @@ impl MachineUpdateModule for DpuNicFirmwareUpdate { { match reprovisioning_err { DatabaseError::NotFoundError { id, .. } => { - tracing::warn!( - "failed to trigger reprovisioning for managed host : {} - no update match for id: {}", - host_machine_id, - id - ); + carbide_instrument::emit(FirmwareUpdateFailed { + target: FirmwareUpdateTarget::DpuNic, + cause: FirmwareUpdateFailureCause::NoUpdateMatch, + machine_id: host_machine_id, + unmatched_dpu_machine_id: id, + firmware_version: String::new(), + }); continue; } _ => { @@ -139,6 +148,15 @@ impl MachineUpdateModule for DpuNicFirmwareUpdate { txn.commit().await?; + // Counted only once the trigger is committed: a DPU that left + // ready between snapshot and trigger is a NoUpdateMatch failure, + // not a started update. + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::DpuNic, + phase: FirmwareUpdatePhase::Started, + machine_id: host_machine_id, + detail: dpu_update_string, + }); updates_started.insert(host_machine_id); } @@ -163,13 +181,26 @@ impl MachineUpdateModule for DpuNicFirmwareUpdate { machine_id = %updated_machine.dpu_machine_id, "Failed to remove machine update markers: {}", e ); + } else if let Ok(mut reported) = self.reported_wrong_versions.lock() { + reported.retain(|(dpu, _)| *dpu != updated_machine.dpu_machine_id); } - } else { - tracing::warn!( - machine_id = %updated_machine.dpu_machine_id, - firmware_version = %updated_machine.firmware_version, - "Incorrect firmware version after attempted update" - ); + } else if self + .reported_wrong_versions + .lock() + .is_ok_and(|mut reported| { + reported.insert(( + updated_machine.dpu_machine_id, + updated_machine.firmware_version.clone(), + )) + }) + { + carbide_instrument::emit(FirmwareUpdateFailed { + target: FirmwareUpdateTarget::DpuNic, + cause: FirmwareUpdateFailureCause::WrongVersionAfterUpdate, + machine_id: updated_machine.dpu_machine_id, + unmatched_dpu_machine_id: String::new(), + firmware_version: updated_machine.firmware_version, + }); } } Ok(()) @@ -243,6 +274,7 @@ impl DpuNicFirmwareUpdate { let mut metrics = DpuNicFirmwareUpdateMetrics::new(); metrics.register_callbacks(&meter); Some(DpuNicFirmwareUpdate { + reported_wrong_versions: std::sync::Mutex::new(HashSet::new()), metrics: Some(metrics), config, dpf, diff --git a/crates/api-core/src/machine_update_manager/host_firmware.rs b/crates/api-core/src/machine_update_manager/host_firmware.rs index d811ff7e5d..d0ace20657 100644 --- a/crates/api-core/src/machine_update_manager/host_firmware.rs +++ b/crates/api-core/src/machine_update_manager/host_firmware.rs @@ -32,6 +32,7 @@ use sqlx::PgConnection; use tokio::sync::Mutex; use super::machine_update_module::MachineUpdateModule; +use super::metrics::{FirmwareUpdatePhase, FirmwareUpdateProgress, FirmwareUpdateTarget}; use crate::CarbideResult; use crate::cfg::file::CarbideConfig; @@ -90,8 +91,6 @@ impl MachineUpdateModule for HostFirmwareUpdate { continue; } - tracing::info!("Moving {} to host reprovision", machine_update); - db::host_machine_update::trigger_host_reprovisioning_request( &mut txn, "Automated", @@ -99,6 +98,15 @@ impl MachineUpdateModule for HostFirmwareUpdate { ) .await?; + // Counted after the trigger succeeds; the commit below spans the + // whole batch, so a later DB error can re-count machines on the + // next pass -- the same repeat-on-retry the old log line had. + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::Host, + phase: FirmwareUpdatePhase::Started, + machine_id: *machine_update, + detail: String::new(), + }); updates_started.insert(*machine_update); } @@ -109,18 +117,21 @@ impl MachineUpdateModule for HostFirmwareUpdate { async fn clear_completed_updates(&self, txn: &mut PgConnection) -> CarbideResult<()> { let completed = db::host_machine_update::find_completed_updates(txn).await?; - if !completed.is_empty() { - tracing::info!("Completed host firmware updates: {completed:?}"); - for machine in completed { - db::machine::remove_health_report( - txn, - &machine, - health_report::HealthReportApplyMode::Merge, - HOST_FW_UPDATE_HEALTH_REPORT_SOURCE, - ) - .await?; - db::machine::update_update_complete(&machine, true, txn).await?; - } + for machine in completed { + db::machine::remove_health_report( + txn, + &machine, + health_report::HealthReportApplyMode::Merge, + HOST_FW_UPDATE_HEALTH_REPORT_SOURCE, + ) + .await?; + db::machine::update_update_complete(&machine, true, txn).await?; + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::Host, + phase: FirmwareUpdatePhase::Completed, + machine_id: machine, + detail: String::new(), + }); } Ok(()) } diff --git a/crates/api-core/src/machine_update_manager/metrics.rs b/crates/api-core/src/machine_update_manager/metrics.rs index 2775e5ff78..72b9021316 100644 --- a/crates/api-core/src/machine_update_manager/metrics.rs +++ b/crates/api-core/src/machine_update_manager/metrics.rs @@ -17,6 +17,7 @@ use std::sync::Arc; use std::sync::atomic::{AtomicU64, Ordering}; +use carbide_uuid::machine::MachineId; use opentelemetry::metrics::Meter; pub struct MachineUpdateManagerMetrics { @@ -69,3 +70,237 @@ impl MachineUpdateManagerMetrics { .build(); } } + +/// The device class a firmware update targets: the `target` label shared by +/// [`FirmwareUpdateProgress`] and [`FirmwareUpdateFailed`]. +#[derive(Debug, Clone, Copy, PartialEq, Eq, carbide_instrument::LabelValue)] +pub enum FirmwareUpdateTarget { + /// Host firmware, applied through host reprovisioning. + Host, + /// DPU NIC firmware, applied through DPU reprovisioning. + DpuNic, + /// SuperNIC firmware, applied through the DPA scout flow. + SuperNic, +} + +/// The phase a firmware update just reached, as the `phase` label on +/// [`FirmwareUpdateProgress`]. +#[derive(Debug, Clone, Copy, PartialEq, Eq, carbide_instrument::LabelValue)] +pub enum FirmwareUpdatePhase { + Started, + Completed, +} + +/// A firmware update reached a phase. For the `host` target both phases +/// fire, so the started-to-completed gap is the in-flight backlog: a started +/// series that moves while completed stays flat points at updates that never +/// finish. The `dpu_nic` and `super_nic` targets emit `started` only -- +/// completion shows in their own state flows -- and a SuperNIC re-counts one +/// `started` per scout pass while a device stays mismatched, since each pass +/// issues a real apply command. Both phases are at-least-once on transient +/// database errors: the update manager's batch transaction can roll back +/// after an emit, and the next pass re-counts -- the same repeat-on-retry +/// the log lines always had. +#[derive(carbide_instrument::Event)] +#[event( + name = "carbide_firmware_updates_total", + component = "nico-api", + log = info, + metric = counter, + message = "Firmware update progress", + describe = "Number of firmware updates started and completed, by update target and phase" +)] +pub struct FirmwareUpdateProgress { + #[label] + pub target: FirmwareUpdateTarget, + #[label] + pub phase: FirmwareUpdatePhase, + /// The host being reprovisioned (Host), the host whose DPUs update + /// (DpuNic), or the machine holding the device (SuperNic). + #[context] + pub machine_id: MachineId, + /// What the site knows beyond the machine id: the DPU list with firmware + /// versions for DpuNic, the device identity and observed/expected + /// versions for SuperNic. For Host it is empty on automatic starts and + /// names the initiator on operator-initiated ones. + #[context] + pub detail: String, +} + +/// Why a firmware update failed, as the `cause` label on +/// [`FirmwareUpdateFailed`]. +#[derive(Debug, Clone, Copy, PartialEq, Eq, carbide_instrument::LabelValue)] +pub enum FirmwareUpdateFailureCause { + /// Triggering reprovisioning found no ready machine row to update. + NoUpdateMatch, + /// The update ran but the device still reports an unexpected version. + WrongVersionAfterUpdate, +} + +/// A firmware update attempt failed. The per-target, per-cause rate is the +/// alert; the log line names the machine and version involved. +#[derive(carbide_instrument::Event)] +#[event( + name = "carbide_firmware_update_failures_total", + component = "nico-api", + log = warn, + metric = counter, + message = "Firmware update failed", + describe = "Number of firmware update failures, by update target and cause" +)] +pub struct FirmwareUpdateFailed { + #[label] + pub target: FirmwareUpdateTarget, + #[label] + pub cause: FirmwareUpdateFailureCause, + /// The host whose update could not start (NoUpdateMatch) or the DPU + /// reporting the wrong version (WrongVersionAfterUpdate). + #[context] + pub machine_id: MachineId, + /// The DPU the reprovisioning trigger could not match (NoUpdateMatch); + /// empty otherwise. + #[context] + pub unmatched_dpu_machine_id: String, + /// The firmware version observed after the attempted update + /// (WrongVersionAfterUpdate); empty otherwise. + #[context] + pub firmware_version: String, +} + +#[cfg(test)] +mod tests { + use std::str::FromStr as _; + + use carbide_instrument::testing::{CapturedLog, MetricsCapture, capture_logs}; + + use super::*; + + fn field<'a>(log: &'a CapturedLog, name: &str) -> Option<&'a str> { + log.fields + .iter() + .find(|(key, _)| key == name) + .map(|(_, value)| value.as_str()) + } + + fn machine_id() -> MachineId { + MachineId::from_str("fm100hseddco33hvlofuqvg543p6p9aj60g76q5cq491g9m9tgtf2dk0530") + .expect("valid machine id") + } + + /// One emit writes the INFO progress line (machine id plus the site's + /// detail) and moves `carbide_firmware_updates_total` under the site's + /// target and phase. + #[test] + fn firmware_update_progress_logs_info_and_counts() { + let metrics = MetricsCapture::start(); + let logs = capture_logs(|| { + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::SuperNic, + phase: FirmwareUpdatePhase::Started, + machine_id: machine_id(), + detail: "pci_name=0000:cc:00.0 observed_fw_version=Some(\"28.39.1000\") \ + expected_fw_version=28.39.1002" + .to_string(), + }); + }); + + assert_eq!(logs.len(), 1); + assert_eq!(logs[0].level, tracing::Level::INFO); + assert_eq!(logs[0].message, "Firmware update progress"); + assert_eq!(field(&logs[0], "target"), Some("super_nic")); + assert_eq!(field(&logs[0], "phase"), Some("started")); + let id = machine_id().to_string(); + assert_eq!(field(&logs[0], "machine_id"), Some(id.as_str())); + assert!( + field(&logs[0], "detail") + .expect("detail field") + .contains("expected_fw_version=28.39.1002") + ); + + assert_eq!( + metrics.counter_delta( + "carbide_firmware_updates_total", + &[("target", "super_nic"), ("phase", "started")], + ), + 1.0 + ); + } + + /// The phase label separates the started and completed series for the + /// same target: one update crossing both phases moves each counter once. + #[test] + fn firmware_update_progress_counts_each_phase_separately() { + let metrics = MetricsCapture::start(); + capture_logs(|| { + for phase in [FirmwareUpdatePhase::Started, FirmwareUpdatePhase::Completed] { + carbide_instrument::emit(FirmwareUpdateProgress { + target: FirmwareUpdateTarget::Host, + phase, + machine_id: machine_id(), + detail: String::new(), + }); + } + }); + + for phase in ["started", "completed"] { + assert_eq!( + metrics.counter_delta( + "carbide_firmware_updates_total", + &[("target", "host"), ("phase", phase)], + ), + 1.0, + "phase {phase}" + ); + } + } + + /// A failure emit writes the WARN line with its cause's context and moves + /// `carbide_firmware_update_failures_total`; the two causes count as + /// independent series. + #[test] + fn firmware_update_failed_logs_warn_and_counts_by_cause() { + let metrics = MetricsCapture::start(); + let logs = capture_logs(|| { + carbide_instrument::emit(FirmwareUpdateFailed { + target: FirmwareUpdateTarget::DpuNic, + cause: FirmwareUpdateFailureCause::NoUpdateMatch, + machine_id: machine_id(), + unmatched_dpu_machine_id: + "fm100ptrh18t1lrjg2pqagkh3sfigr9m65dejvkq168ako07sc0uibpp5q0".to_string(), + firmware_version: String::new(), + }); + carbide_instrument::emit(FirmwareUpdateFailed { + target: FirmwareUpdateTarget::DpuNic, + cause: FirmwareUpdateFailureCause::WrongVersionAfterUpdate, + machine_id: machine_id(), + unmatched_dpu_machine_id: String::new(), + firmware_version: "11.10.1000".to_string(), + }); + }); + + assert_eq!(logs.len(), 2); + assert!(logs.iter().all(|log| log.level == tracing::Level::WARN)); + assert!( + logs.iter() + .all(|log| log.message == "Firmware update failed") + ); + assert_eq!(field(&logs[0], "cause"), Some("no_update_match")); + assert_eq!( + field(&logs[0], "unmatched_dpu_machine_id"), + Some("fm100ptrh18t1lrjg2pqagkh3sfigr9m65dejvkq168ako07sc0uibpp5q0") + ); + assert_eq!(field(&logs[1], "cause"), Some("wrong_version_after_update")); + assert_eq!(field(&logs[1], "firmware_version"), Some("11.10.1000")); + + for cause in ["no_update_match", "wrong_version_after_update"] { + assert_eq!( + metrics.counter_delta( + "carbide_firmware_update_failures_total", + &[("target", "dpu_nic"), ("cause", cause)], + ), + 1.0, + "cause {cause}" + ); + } + } +} diff --git a/crates/api-core/src/tests/dpu_nic_firmware.rs b/crates/api-core/src/tests/dpu_nic_firmware.rs index 43eb90493d..f553fa259f 100644 --- a/crates/api-core/src/tests/dpu_nic_firmware.rs +++ b/crates/api-core/src/tests/dpu_nic_firmware.rs @@ -17,6 +17,7 @@ use std::collections::HashSet; use std::string::ToString; +use carbide_instrument::testing::MetricsCapture; use carbide_machine_controller::health_report::create_host_update_health_report_dpufw; use common::api_fixtures::{create_managed_host, create_managed_host_multi_dpu, create_test_env}; use model::machine::LoadSnapshotOptions; @@ -40,6 +41,7 @@ async fn test_start_updates(pool: sqlx::PgPool) -> Result<(), Box Result<(), Box Result<(), Box= 1.0 + ); + // Check if health override is placed let managed_host = managed_host.snapshot(&mut txn).await; @@ -89,6 +104,7 @@ async fn test_start_updates_with_multidpu( txn.commit().await?; let dpu_nic_firmware_update = DpuNicFirmwareUpdate { + reported_wrong_versions: std::sync::Mutex::new(std::collections::HashSet::new()), metrics: None, config: env.config.clone(), dpf: None, @@ -132,6 +148,7 @@ async fn test_get_updates_in_progress( managed_host.update_nic_firmware_version(&mut txn).await?; txn.commit().await?; let dpu_nic_firmware_update = DpuNicFirmwareUpdate { + reported_wrong_versions: std::sync::Mutex::new(std::collections::HashSet::new()), metrics: None, config: env.config.clone(), dpf: None, @@ -180,6 +197,7 @@ async fn test_check_for_updates(pool: sqlx::PgPool) -> Result<(), Boxcarbide_endpoint_exploration_success_countgaugeThe amount of endpoint explorations that have been successful carbide_endpoint_explorations_countgaugeThe amount of endpoint explorations that have been attempted carbide_external_call_duration_millisecondshistogramDuration of outbound calls by backend, operation, and outcome; the _count series, split by outcome, gives the request and error rates. +carbide_firmware_update_failures_totalcounterNumber of firmware update failures, by update target and cause +carbide_firmware_updates_totalcounterNumber of firmware updates started and completed, by update target and phase carbide_gpus_in_use_countgaugeThe total number of GPUs that are actively used by tenants in instances in the NICo deployment carbide_gpus_total_countgaugeThe total number of GPUs available in the NICo deployment carbide_gpus_usable_countgaugeThe remaining number of GPUs in the NICo deployment which are available for immediate instance creation